Re: Unexpected trouble from pg_basebackup

On Tue, Oct 4, 2016 at 10:49 PM, Magnus Hagander <magnus@hagander.net> wrote:

On Tue, Oct 4, 2016 at 10:42 PM, otheus uibk <otheus.uibk@gmail.com> wrote:

After a 3 to 4 minute delay, pg_basebackup started doing it's thing and finished within a few minutes. So now the question is: why the startup delay?

Sounds to me like it's doing a CHECKPOINT with spreading, which make it take time. Try with "-c fast" and see if the problem goes away.

Maybe not too far off. 

2016-10-04 17:43:40.620 GMT                             57eb90a0.6e07   402     00000   LOG:  checkpoint complete: wrote 12799 buffers (1.0%); 0 transaction log file(s) added, 0 removed, 5 recycled; write=1389.348 s, sync=0.033 s, total=1389.400 s; sync files=240, longest=0.003 s, average=0.000 s; distance=92915 kB, estimate=129373 kB

2016-10-04 18:20:31.714 GMT                             57eb90a0.6e07   403     00000   LOG:  checkpoint starting: time

2016-10-04 18:39:19.870 GMT                             57eb90a0.6e07   404     00000   LOG:  checkpoint complete: wrote 10265 buffers (0.8%); 0 transaction log file(s) added, 0 removed, 4 recycled; write=1128.118 s, sync=0.023 s, total=1128.155 s; sync files=190, longest=0.002 s, average=0.000 s; distance=73419 kB, estimate=123778 kB

2016-10-04 19:07:12.647 GMT     [unknown]       pgsync  57f3fde0.52e3   2       00000   LOG:  replication connection authorized: user=pgsync

2016-10-04 19:07:12.703 GMT                             57eb90a0.6e07   405     00000   LOG:  checkpoint starting: force wait

2016-10-04 19:20:32.879 GMT     [unknown]       pgsync  57f40100.5891   2       00000   LOG:  replication connection authorized: user=pgsync

2016-10-04 19:23:05.249 GMT                             57eb90a0.6e07   406     00000   LOG:  checkpoint complete: wrote 8638 buffers (0.7%); 0 transaction log file(s) added, 0 removed, 5 recycled; write=952.514 s, sync=0.016 s, total=952.546 s; sync files=238, longest=0.002 s, average=0.000 s; distance=68257 kB, estimate=118226 kB

2016-10-04 19:23:05.249 GMT                             57eb90a0.6e07   407     00000   LOG:  checkpoint starting: force wait

2016-10-04 19:28:52.232 GMT                             57eb90a0.6e07   408     00000   LOG:  checkpoint complete: wrote 3102 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=346.957 s, sync=0.018 s, total=346.982 s; sync files=149, longest=0.002 s, average=0.000 s; distance=36016 kB, estimate=110005 kB

2016-10-04 19:30:31.922 GMT     [unknown]       pgsync  57f40357.5c70   2       00000   LOG:  replication connection authorized: user=pgsync

2016-10-04 19:30:31.932 GMT                             57eb90a0.6e07   409     00000   LOG:  checkpoint starting: force wait

2016-10-04 19:33:40.857 GMT                             57eb90a0.6e07   410     00000   LOG:  checkpoint complete: wrote 1763 buffers (0.1%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=188.886 s, sync=0.030 s, total=188.924 s; sync files=125, longest=0.004 s, average=0.000 s; distance=13135 kB, estimate=100318 kB

OK, so what was happening is that the checkpoints were taking 5 to 15 minutes minutes, and aborted basebackups were triggering new checkpoints which waited on the previous ones.

Is it possible the new environment is not high-performance enough??

possibly relevant configuration change:

   checkpoint_timeout=1h