Infrastructure at your Service

Daniel Westermann

pg_basebackup and redirecting progress messages to a file

Recently I came over that commit and wondered what that is about. The answer is quite simple but I didn’t know that this issue existed. Basically it is about how progress messages are written to screen and how they are written to a file. Lets have a look.

When your run pg_basebackup with progress messages and in verbose mode the output looks like this:

[email protected]:/home/postgres/ [PG10] pg_basebackup --pgdata=/var/tmp/aa --verbose --progress 
pg_basebackup: initiating base backup, waiting for checkpoint to complete
pg_basebackup: checkpoint completed
pg_basebackup: write-ahead log start point: 4/30000028 on timeline 1
pg_basebackup: starting background WAL receiver
593320/593320 kB (100%), 1/1 tablespace                                         
pg_basebackup: write-ahead log end point: 4/30000130
pg_basebackup: waiting for background process to finish streaming ...
pg_basebackup: base backup completed

You’ll notice that the highlighted line always is overwritten on screen until we reach one hundred percent. Looking at that line when pg_basebackup is running will give you an estimate on how long it will take and you will see which file it is currently working on. When you do the same thing but kick it in the background like this:

[email protected]:/home/postgres/ [PG10] pg_basebackup --version
pg_basebackup (PostgreSQL) 10.0 
[email protected]:/home/postgres/ [PG10] mkdir /var/tmp/aa
[email protected]:/home/postgres/ [PG10] nohup pg_basebackup --pgdata=/var/tmp/aa --verbose --progress  > /tmp/a.log 2>&1  &

… you will have the same output in the log file:

[email protected]:/home/postgres/ [PG10] cat -f /tmp/a.log
nohup: ignoring input
pg_basebackup: initiating base backup, waiting for checkpoint to complete
pg_basebackup: checkpoint completed
pg_basebackup: write-ahead log start point: 4/28000028 on timeline 1
pg_basebackup: starting background WAL receiver
593315/593315 kB (100%), 1/1 tablespace                                         
pg_basebackup: write-ahead log end point: 4/28000130
pg_basebackup: waiting for background process to finish streaming ...
pg_basebackup: base backup completed

Somehow that was not considered very useful so the commit mentioned above changed that:

[email protected]:/home/postgres/ [PGDEV] pg_basebackup --version
pg_basebackup (PostgreSQL) 11devel
[email protected]:/home/postgres/ [PGDEV] nohup pg_basebackup --pgdata=/var/tmp/aa --verbose --progress  > /tmp/a.log 2>&1  &
[email protected]:/home/postgres/ [PGDEV] cat /tmp/a.log
nohup: ignoring input
pg_basebackup: initiating base backup, waiting for checkpoint to complete
pg_basebackup: checkpoint completed
pg_basebackup: write-ahead log start point: 0/E000028 on timeline 1
pg_basebackup: starting background WAL receiver
pg_basebackup: created temporary replication slot "pg_basebackup_29846"
     0/184659 kB (0%), 0/1 tablespace (/var/tmp/aa/backup_label           )
  1705/184659 kB (0%), 0/1 tablespace (/var/tmp/aa/base/1/1249            )
  4697/184659 kB (2%), 0/1 tablespace (/var/tmp/aa/base/1/2657            )
  8395/184659 kB (4%), 0/1 tablespace (/var/tmp/aa/base/13276/1255        )
 20601/184659 kB (11%), 0/1 tablespace (/var/tmp/aa/base/13277/2670        )
 30614/184659 kB (16%), 0/1 tablespace (/var/tmp/aa/base/16395/2607_vm     )
 45367/184659 kB (24%), 0/1 tablespace (/var/tmp/aa/base/16395/16424       )
 54743/184659 kB (29%), 0/1 tablespace (/var/tmp/aa/base/16395/16424       )
 74327/184659 kB (40%), 0/1 tablespace (/var/tmp/aa/base/16395/16424       )
118807/184659 kB (64%), 0/1 tablespace (/var/tmp/aa/base/16395/16424       )
146647/184659 kB (79%), 0/1 tablespace (/var/tmp/aa/base/16395/16424       )
175197/184659 kB (94%), 0/1 tablespace (/var/tmp/aa/base/16395/16432       )
184668/184668 kB (100%), 0/1 tablespace (/var/tmp/aa/global/pg_control      )
184668/184668 kB (100%), 0/1 tablespace (/var/tmp/aa/global/pg_control      )
184668/184668 kB (100%), 1/1 tablespace                                         
pg_basebackup: write-ahead log end point: 0/E000168
pg_basebackup: waiting for background process to finish streaming ...
pg_basebackup: base backup completed

When you redirect the output into a file you can see much more steps in the log file compared to what we saw before (only a single line which is overwritten all the time). Seems to be a good change.

Leave a Reply

This site uses Akismet to reduce spam. Learn how your comment data is processed.

Daniel Westermann
Daniel Westermann

Principal Consultant & Technology Leader Open Infrastructure