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:

postgres@pgbox:/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:

postgres@pgbox:/home/postgres/ [PG10] pg_basebackup --version
pg_basebackup (PostgreSQL) 10.0 
postgres@pgbox:/home/postgres/ [PG10] mkdir /var/tmp/aa
postgres@pgbox:/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:

postgres@pgbox:/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:

postgres@pgbox:/home/postgres/ [PGDEV] pg_basebackup --version
pg_basebackup (PostgreSQL) 11devel
postgres@pgbox:/home/postgres/ [PGDEV] nohup pg_basebackup --pgdata=/var/tmp/aa --verbose --progress  > /tmp/a.log 2>&1  &
postgres@pgbox:/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.