pg_stop_backup running for 10h?

Hi all,

I'm using OmniPITR to build a new slave. According to pg_stat_activity, pg_stop_backup has been running for nearly 11 hours. The WAL archive command is running just fine and reporting "Segment X successfully sent to all destinations".

I had the same issue almost a year ago (http://www.postgresql.org/message-id/9CC57302-10F8-4678-BBD3-028EC6B57051@teksol.info) but don't have permission issues this time around.

What could cause a pg_stop_backup() to run for such a long time?

Should I stop, upgrade omnipitr and start again?

Thanks!
François

---

PostgreSQL 9.1.11 on x86_64-unknown-linux-gnu, compiled by gcc (Ubuntu/Linaro 4.6.3-1ubuntu5) 4.6.3, 64-bit
omnipitr-backup-master ver. 1.1.0

# postgresql.conf

# ...
archive_command = '/usr/local/omnipitr/bin/omnipitr-archive --log /var/log/omnipitr/archive-^Y-^m-^d.log --state-dir /var/lib/postgresql/omnipitr-state --dst-remote gzip=root(at)kalanchoe(dot)ca(dot)seevibes(dot)com:/var/backups/seevibes/wal/dbanalytics.production/ --temp /var/tmp/omnipitr --rsync-path=/usr/local/bin/wal-syncer --verbose "%p" --dst-backup /var/tmp/seevibes/pg.backup'

omnipitr-backup-master was launched like this:

# sudo -u postgres /usr/local/lib/omnipitr/bin/omnipitr-backup-master -D /var/lib/postgresql/9.1/main --dst-direct gzip=root(at)kalanchoe(dot)ca(dot)seevibes(dot)com:/var/backups/seevibes/dbanalytics.production --log /var/log/omnipitr/backup-master.log --verbose --xlogs /var/tmp/seevibes/pg.backup --ssh-path /usr/local/bin/wal-sender

wal-syncer and wal-sender are simple wrappers over rsync and ssh, respectively, which use the -i option to choose the correct private key file.

# ls -ld /var/tmp/seevibes/pg.backup*
lrwxrwxrwx 1 postgres postgres 45 Jan 10 21:35 /var/tmp/seevibes/pg.backup -> /var/tmp/seevibes/pg.backup.real/main/pg_xlog
drwxrwxr-x 3 postgres postgres 4096 Jan 10 21:35 /var/tmp/seevibes/pg.backup.real

omnipitr-archive's log has many entries like this (and 10 hours ago, it was the same thing):

2014-01-11 22:20:53.142844 +0000 : 32091 : omnipitr-archive : LOG : Called with parameters: --log /var/log/omnipitr/archive-^Y-^m-^d.log --state-dir /var/lib/postgresql/omnipitr-state --dst-remote gzip=root(at)kalanchoe(dot)ca(dot)seevibes(dot)com:/var/backups/seevibes/wal/dbanalytics.production/ --temp /var/tmp/omnipitr --rsync-path=/usr/local/bin/wal-syncer --verbose pg_xlog/0000000700002476000000A0 --dst-backup /var/tmp/seevibes/pg.backup
2014-01-11 22:20:53.706888 +0000 : 32091 : omnipitr-archive : LOG : Timer [Compressing with gzip] took: 0.315s
2014-01-11 22:20:54.149710 +0000 : 32091 : omnipitr-archive : LOG : Sending ./pg_xlog/0000000700002476000000A0 to /var/tmp/seevibes/pg.backup/0000000700002476000000A0 ended in 0.158532s
2014-01-11 22:20:56.765873 +0000 : 32091 : omnipitr-archive : LOG : Sending /var/tmp/omnipitr/omnipitr-archive/32091/0000000700002476000000A0/0000000700002476000000A0.gz to root(at)kalanchoe(dot)ca(dot)seevibes(dot)com:/var/backups/seevibes/wal/dbanalytics.production/0000000700002476000000A0.gz ended in 2.485214s
2014-01-11 22:20:57.009521 +0000 : 32091 : omnipitr-archive : LOG : Timer [Segment delivery] took: 3.019s
2014-01-11 22:20:57.105550 +0000 : 32091 : omnipitr-archive : LOG : Segment ./pg_xlog/0000000700002476000000A0 successfully sent to all destinations.

omnipitr-backup-master's log has this:

2014-01-10 21:53:01.534477 +0000 : 22722 : omnipitr-backup-master : LOG : Timer [SELECT pg_start_backup('omnipitr')] took: 1080.943s
2014-01-10 21:53:01.752511 +0000 : 22722 : omnipitr-backup-master : LOG : pg_start_backup('omnipitr') returned 2484/5AFCBB48.
2014-01-10 21:53:01.895868 +0000 : 22722 : omnipitr-backup-master : LOG : Actual command to make tarballs: exec nice tar cf \- \-\-exclude\=pg_log\/\* \-\-exclude\=pg_xlog\/0\* \-\-exclude\=pg_xlog\/archive_status\/\* \-\-exclude\=postmaster\.pid main 2> \/tmp\/omnipitr\-backup\-master\/22722\/tar\.stderr | nice gzip \-\-stdout \- | \/usr\/local\/bin\/wal\-sender root\(at)kalanchoe\(dot)ca\(dot)seevibes\(dot)com cat\ \-\ \>\ \\\/var\\\/backups\\\/seevibes\\\/dbanalytics\\\.production\\\/skyler\\\.ca\\\.seevibes\\\.com\\\-data\\\-2014\\\-01\\\-10\\\.tar\\\.gz
2014-01-11 11:36:15.305926 +0000 : 22722 : omnipitr-backup-master : LOG : tar stderr:
2014-01-11 11:36:16.161887 +0000 : 22722 : omnipitr-backup-master : LOG : ==============================================
2014-01-11 11:36:16.199998 +0000 : 22722 : omnipitr-backup-master : LOG : tar: main/base/18332/t4_26246478_fsm: File removed before we read it
2014-01-11 11:36:16.199998 +0000 : 22722 : omnipitr-backup-master : LOG : tar: main/base/18332/t23_26246745: File removed before we read it
2014-01-11 11:36:16.199998 +0000 : 22722 : omnipitr-backup-master : LOG : tar: main/base/18332/t20_26246658: File removed before we read it
...
2014-01-11 11:36:16.199998 +0000 : 22722 : omnipitr-backup-master : LOG : tar: main/base/18332/25968250.1: file changed as we read it
2014-01-11 11:36:16.199998 +0000 : 22722 : omnipitr-backup-master : LOG : tar: main/base/18332: file changed as we read it
2014-01-11 11:36:16.325208 +0000 : 22722 : omnipitr-backup-master : LOG : ==============================================
2014-01-11 11:36:16.423534 +0000 : 22722 : omnipitr-backup-master : LOG : Timer [Compressing $PGDATA] took: 49394.562s