========= iteration 1 -- 1 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 16:56:30 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.11 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 56.0 tps, lat 17.836 ms stddev 17.215 progress: 10.0 s, 74.8 tps, lat 13.355 ms stddev 5.588 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 655 latency average = 15.268 ms latency stddev = 12.225 ms tps = 65.476369 (including connections establishing) tps = 65.494796 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 655 5d67962e9 95f511740 b7087dbe3 912052489 master 6973 a,b,t,h: 100000 1 0 0 445067231 95f511740 d41d8cd98 d41d8cd98 replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 655 5d67962e9 95f511740 b7087dbe3 912052489 master 6973 a,b,t,h: 100000 1 10 655 133bd8bc3 95f511740 b7087dbe3 912052489 replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 655 5d67962e9 95f511740 b7087dbe3 912052489 master 6973 a,b,t,h: 100000 1 10 655 5d67962e9 95f511740 b7087dbe3 912052489 replica ok -- All is well. ========= iteration 2 -- 2 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 16:57:00 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.12 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 25.6 tps, lat 38.977 ms stddev 22.165 progress: 10.0 s, 64.2 tps, lat 15.559 ms stddev 8.822 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 450 latency average = 22.212 ms latency stddev = 17.522 ms tps = 44.994228 (including connections establishing) tps = 45.021467 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 450 7e11a7754 9b1a33e8e f79221f89 041eb476b master 6973 a,b,t,h: 100000 1 10 450 7e11a7754 9b1a33e8e f79221f89 041eb476b replica ok -- All is well. ========= iteration 3 -- 3 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 16:57:19 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.12 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 28.2 tps, lat 35.274 ms stddev 25.319 progress: 10.0 s, 35.0 tps, lat 28.405 ms stddev 14.105 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 317 latency average = 31.560 ms latency stddev = 20.228 ms tps = 31.667394 (including connections establishing) tps = 31.685594 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 317 ae1a5c022 13e26b523 77a409834 5082f5fe7 master 6973 a,b,t,h: 100000 1 10 317 ae1a5c022 13e26b523 77a409834 5082f5fe7 replica ok -- All is well. ========= iteration 4 -- 4 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 16:57:38 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.15 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 30.6 tps, lat 32.594 ms stddev 26.370 progress: 10.0 s, 43.6 tps, lat 22.749 ms stddev 17.206 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 372 latency average = 26.995 ms latency stddev = 22.266 ms tps = 37.023229 (including connections establishing) tps = 37.043157 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 372 46d355156 42522e830 dedc97701 795999d36 master 6973 a,b,t,h: 100000 1 10 277 3d6abf84e 6bc4f7907 19aabab5d 418b4b4e3 replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 372 46d355156 42522e830 dedc97701 795999d36 master 6973 a,b,t,h: 100000 1 10 372 46d355156 42522e830 dedc97701 795999d36 replica ok -- All is well. ========= iteration 5 -- 5 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 16:58:03 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.12 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 25.8 tps, lat 38.518 ms stddev 36.048 progress: 10.0 s, 33.6 tps, lat 29.864 ms stddev 18.031 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 298 latency average = 33.590 ms latency stddev = 27.648 ms tps = 29.759994 (including connections establishing) tps = 29.770185 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 298 3483bff1b 4ad8227f6 96b592aa0 2a46ccc42 master 6973 a,b,t,h: 100000 1 10 298 3483bff1b 4ad8227f6 96b592aa0 2a46ccc42 replica ok -- All is well. ========= iteration 6 -- 6 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 16:58:22 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.13 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 25.8 tps, lat 38.391 ms stddev 23.232 progress: 10.0 s, 65.4 tps, lat 15.418 ms stddev 9.942 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 457 latency average = 22.211 ms latency stddev = 19.218 ms tps = 44.997071 (including connections establishing) tps = 45.023107 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 457 81ed6abe1 45a9a278b 15323506f e8ec488f9 master 6973 a,b,t,h: 100000 1 10 457 81ed6abe1 45a9a278b 15323506f e8ec488f9 replica ok -- All is well. ========= iteration 7 -- 7 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 16:58:41 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 ERROR: could not drop the replication slot "sub1" on publisher DETAIL: The error was: ERROR: replication slot "sub1" is active for PID 532 pub_count -ne 0 - deleting pub1 pub_repl_slot_count -ne 0 - deleting (sub1) pg_drop_replication_slot -------------------------- (1 row) pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.12 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 23.6 tps, lat 41.823 ms stddev 23.505 progress: 10.0 s, 33.8 tps, lat 29.823 ms stddev 18.264 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 288 latency average = 34.887 ms latency stddev = 21.487 ms tps = 28.644145 (including connections establishing) tps = 28.663842 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 288 c47a93546 634356f4f 99ef52004 41a2fc56b master 6973 a,b,t,h: 100000 1 10 288 c47a93546 634356f4f 99ef52004 41a2fc56b replica ok -- All is well. ========= iteration 8 -- 8 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 16:59:03 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.13 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 51.8 tps, lat 19.242 ms stddev 19.579 progress: 10.0 s, 76.4 tps, lat 13.111 ms stddev 5.213 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 642 latency average = 15.582 ms latency stddev = 13.412 ms tps = 64.135532 (including connections establishing) tps = 64.174326 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 642 0a8665b16 d843d2a0f ac8186478 0d4000094 master 6973 a,b,t,h: 100000 0 0 0 e2521a2b8 d41d8cd98 d41d8cd98 d41d8cd98 replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 642 0a8665b16 d843d2a0f ac8186478 0d4000094 master 6973 a,b,t,h: 100000 0 0 0 e2521a2b8 d41d8cd98 d41d8cd98 d41d8cd98 replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 642 0a8665b16 d843d2a0f ac8186478 0d4000094 master 6973 a,b,t,h: 100000 1 10 642 e2521a2b8 d843d2a0f ac8186478 0d4000094 replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 642 0a8665b16 d843d2a0f ac8186478 0d4000094 master 6973 a,b,t,h: 100000 1 10 642 56d1a57b1 d843d2a0f ac8186478 0d4000094 replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 642 0a8665b16 d843d2a0f ac8186478 0d4000094 master 6973 a,b,t,h: 100000 1 10 642 0a8665b16 d843d2a0f ac8186478 0d4000094 replica ok -- All is well. ========= iteration 9 -- 9 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 16:59:44 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.13 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 36.8 tps, lat 27.093 ms stddev 24.429 progress: 10.0 s, 70.2 tps, lat 14.268 ms stddev 15.319 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 536 latency average = 18.667 ms latency stddev = 19.891 ms tps = 53.555483 (including connections establishing) tps = 53.571474 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 536 f7de44da7 b9a467485 2cb255336 3081f04d9 master 6973 a,b,t,h: 100000 1 10 64 da86af27e ae2503c62 2cb255336 9471a9f28 replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 536 f7de44da7 b9a467485 2cb255336 3081f04d9 master 6973 a,b,t,h: 100000 1 10 437 bb22fcc8b d2594eaf2 2cb255336 80cd2b625 replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 536 f7de44da7 b9a467485 2cb255336 3081f04d9 master 6973 a,b,t,h: 100000 1 10 536 f7de44da7 b9a467485 2cb255336 3081f04d9 replica ok -- All is well. ========= iteration 10 -- 10 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 17:00:15 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.12 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 24.8 tps, lat 40.133 ms stddev 26.165 progress: 10.0 s, 33.6 tps, lat 29.646 ms stddev 20.368 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 293 latency average = 34.195 ms latency stddev = 23.602 ms tps = 29.234798 (including connections establishing) tps = 29.243886 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 293 03e007050 6abfd739f 880f25bc0 18d3c97f9 master 6973 a,b,t,h: 100000 1 10 293 03e007050 6abfd739f 880f25bc0 18d3c97f9 replica ok -- All is well. ========= iteration 11 -- 11 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 17:00:34 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.13 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 39.2 tps, lat 25.453 ms stddev 22.981 progress: 10.0 s, 67.8 tps, lat 14.768 ms stddev 13.448 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 536 latency average = 18.670 ms latency stddev = 18.277 ms tps = 53.543896 (including connections establishing) tps = 53.560856 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 536 8bf6e228a 9dfb3d7c4 709b0ce7c ced477219 master 6973 a,b,t,h: 100000 1 10 536 dd26c949b 13ed1592c b0fabfbe8 ced477219 replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 536 8bf6e228a 9dfb3d7c4 709b0ce7c ced477219 master 6973 a,b,t,h: 100000 1 10 536 e386493c7 0f83090b9 5bf09040f ced477219 replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 536 8bf6e228a 9dfb3d7c4 709b0ce7c ced477219 master 6973 a,b,t,h: 100000 1 10 536 8bf6e228a 9dfb3d7c4 709b0ce7c ced477219 replica ok -- All is well. ========= iteration 12 -- 12 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 17:01:04 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.13 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 26.8 tps, lat 37.134 ms stddev 22.342 progress: 10.0 s, 31.8 tps, lat 31.474 ms stddev 17.664 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 294 latency average = 34.028 ms latency stddev = 20.113 ms tps = 29.368784 (including connections establishing) tps = 29.387336 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 294 36d1a16e0 b77bb49ac 7dd83fbf7 aa66b0f4c master 6973 a,b,t,h: 100000 1 10 294 36d1a16e0 b77bb49ac 7dd83fbf7 aa66b0f4c replica ok -- All is well. ========= iteration 13 -- 13 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 17:01:23 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.13 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 41.8 tps, lat 23.868 ms stddev 21.302 progress: 10.0 s, 73.2 tps, lat 13.646 ms stddev 7.509 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 576 latency average = 17.352 ms latency stddev = 14.989 ms tps = 57.595191 (including connections establishing) tps = 57.629411 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 576 80fbe1d68 d0a0a9b35 985be4b2f c72ff5ee1 master 6973 a,b,t,h: 100000 1 10 291 05b8c3627 03c86f773 985be4b2f c96ec2852 replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 576 80fbe1d68 d0a0a9b35 985be4b2f c72ff5ee1 master 6973 a,b,t,h: 100000 1 10 576 80fbe1d68 d0a0a9b35 985be4b2f c72ff5ee1 replica ok -- All is well. ========= iteration 14 -- 14 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 17:01:48 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.13 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 19.4 tps, lat 51.272 ms stddev 32.219 progress: 10.0 s, 36.2 tps, lat 27.724 ms stddev 10.526 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 279 latency average = 35.894 ms latency stddev = 23.641 ms tps = 27.843435 (including connections establishing) tps = 27.859672 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 279 c608517c2 8eb52dda4 4f745f462 f24a05dbb master 6973 a,b,t,h: 100000 1 10 279 c608517c2 8eb52dda4 4f745f462 f24a05dbb replica ok -- All is well. ========= iteration 15 -- 15 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 17:02:07 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.12 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 56.4 tps, lat 17.678 ms stddev 17.385 progress: 10.0 s, 41.4 tps, lat 24.007 ms stddev 27.795 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 490 latency average = 20.400 ms latency stddev = 22.605 ms tps = 48.991121 (including connections establishing) tps = 49.018956 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 490 fa35ea96f 59a7257f0 50bbe1ef5 26e455ead master 6973 a,b,t,h: 99999 1 0 0 ebec15d82 59a7257f0 d41d8cd98 d41d8cd98 replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 490 fa35ea96f 59a7257f0 50bbe1ef5 26e455ead master 6973 a,b,t,h: 99999 1 10 490 e8a72dae8 59a7257f0 50bbe1ef5 26e455ead replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 490 fa35ea96f 59a7257f0 50bbe1ef5 26e455ead master 6973 a,b,t,h: 99999 1 10 490 9f6aa83bc 59a7257f0 50bbe1ef5 26e455ead replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 490 fa35ea96f 59a7257f0 50bbe1ef5 26e455ead master 6973 a,b,t,h: 99999 1 10 490 9f6aa83bc 59a7257f0 50bbe1ef5 26e455ead replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 490 fa35ea96f 59a7257f0 50bbe1ef5 26e455ead master 6973 a,b,t,h: 99999 1 10 490 9f6aa83bc 59a7257f0 50bbe1ef5 26e455ead replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 490 fa35ea96f 59a7257f0 50bbe1ef5 26e455ead master 6973 a,b,t,h: 99999 1 10 490 9f6aa83bc 59a7257f0 50bbe1ef5 26e455ead replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 490 fa35ea96f 59a7257f0 50bbe1ef5 26e455ead master 6973 a,b,t,h: 99999 1 10 490 9f6aa83bc 59a7257f0 50bbe1ef5 26e455ead replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 490 fa35ea96f 59a7257f0 50bbe1ef5 26e455ead master 6973 a,b,t,h: 99999 1 10 490 9f6aa83bc 59a7257f0 50bbe1ef5 26e455ead replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 490 fa35ea96f 59a7257f0 50bbe1ef5 26e455ead master 6973 a,b,t,h: 99999 1 10 490 9f6aa83bc 59a7257f0 50bbe1ef5 26e455ead replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 490 fa35ea96f 59a7257f0 50bbe1ef5 26e455ead master 6973 a,b,t,h: 99999 1 10 490 9f6aa83bc 59a7257f0 50bbe1ef5 26e455ead replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 490 fa35ea96f 59a7257f0 50bbe1ef5 26e455ead master 6973 a,b,t,h: 99999 1 10 490 9f6aa83bc 59a7257f0 50bbe1ef5 26e455ead replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 490 fa35ea96f 59a7257f0 50bbe1ef5 26e455ead master 6973 a,b,t,h: 99999 1 10 490 9f6aa83bc 59a7257f0 50bbe1ef5 26e455ead replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 490 fa35ea96f 59a7257f0 50bbe1ef5 26e455ead master 6973 a,b,t,h: 99999 1 10 490 9f6aa83bc 59a7257f0 50bbe1ef5 26e455ead replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 490 fa35ea96f 59a7257f0 50bbe1ef5 26e455ead master 6973 a,b,t,h: 99999 1 10 490 9f6aa83bc 59a7257f0 50bbe1ef5 26e455ead replica NOK -- Not good, but breaking out of wait (waited more than 60s) ========= iteration 16 -- 16 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 17:03:40 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.12 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 24.2 tps, lat 41.249 ms stddev 35.911 progress: 10.0 s, 36.6 tps, lat 27.286 ms stddev 13.061 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 305 latency average = 32.814 ms latency stddev = 25.706 ms tps = 30.464505 (including connections establishing) tps = 30.474466 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 305 e27d3175a 133452915 c17dce2a3 e629b950f master 6973 a,b,t,h: 100000 1 10 305 e27d3175a 133452915 c17dce2a3 e629b950f replica ok -- All is well. ========= iteration 17 -- 17 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 17:03:59 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.12 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 27.2 tps, lat 36.693 ms stddev 22.821 progress: 10.0 s, 35.8 tps, lat 27.694 ms stddev 11.254 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 316 latency average = 31.631 ms latency stddev = 17.792 ms tps = 31.596090 (including connections establishing) tps = 31.614290 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 316 6676adc4b 44b5e5c13 65a039acd c3b5b5ec6 master 6973 a,b,t,h: 100000 1 10 316 6676adc4b 44b5e5c13 65a039acd c3b5b5ec6 replica ok -- All is well. ========= iteration 18 -- 18 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 17:04:18 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.13 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 59.0 tps, lat 16.909 ms stddev 16.704 progress: 10.0 s, 60.0 tps, lat 16.652 ms stddev 14.429 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 596 latency average = 16.771 ms latency stddev = 15.587 ms tps = 59.589987 (including connections establishing) tps = 59.625055 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 596 b4780d518 10701ff76 5f93b5068 e92ced5d4 master 6973 a,b,t,h: 100000 1 0 403 236dd3fd4 5be21a47f d41d8cd98 812fb5a7f replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 596 b4780d518 10701ff76 5f93b5068 e92ced5d4 master 6973 a,b,t,h: 100000 1 0 403 236dd3fd4 5be21a47f d41d8cd98 812fb5a7f replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 596 b4780d518 10701ff76 5f93b5068 e92ced5d4 master 6973 a,b,t,h: 100000 1 10 403 2a08d0e8f 5be21a47f 5f93b5068 812fb5a7f replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 596 b4780d518 10701ff76 5f93b5068 e92ced5d4 master 6973 a,b,t,h: 100000 1 10 472 9c595e311 953767beb 5f93b5068 dd07d16bf replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 596 b4780d518 10701ff76 5f93b5068 e92ced5d4 master 6973 a,b,t,h: 100000 1 10 596 b4780d518 10701ff76 5f93b5068 e92ced5d4 replica ok -- All is well. ========= iteration 19 -- 19 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 17:04:59 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.13 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 29.4 tps, lat 33.919 ms stddev 32.136 progress: 10.0 s, 61.2 tps, lat 16.360 ms stddev 19.362 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 454 latency average = 22.088 ms latency stddev = 25.591 ms tps = 45.239145 (including connections establishing) tps = 45.272076 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 454 5e842b62a e7984f38b c0eac83a5 c99dfa7ae master 6973 a,b,t,h: 100000 1 10 454 5e842b62a e7984f38b c0eac83a5 c99dfa7ae replica ok -- All is well. ========= iteration 20 -- 20 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 17:05:19 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.13 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 25.0 tps, lat 39.704 ms stddev 37.274 progress: 10.0 s, 49.4 tps, lat 20.364 ms stddev 14.614 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 373 latency average = 26.823 ms latency stddev = 26.284 ms tps = 37.270345 (including connections establishing) tps = 37.281458 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 373 16796b6c9 cfde9cbac 9eca429c7 6ff3604e0 master 6973 a,b,t,h: 100000 1 10 373 16796b6c9 cfde9cbac 9eca429c7 6ff3604e0 replica ok -- All is well. ========= iteration 21 -- 21 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 17:05:38 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.13 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 22.8 tps, lat 43.744 ms stddev 47.169 progress: 10.0 s, 31.6 tps, lat 31.556 ms stddev 24.941 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 273 latency average = 36.744 ms latency stddev = 36.427 ms tps = 27.200766 (including connections establishing) tps = 27.214876 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 273 18c44b613 09987cff7 753cab497 927da1c00 master 6973 a,b,t,h: 100000 1 10 273 18c44b613 09987cff7 753cab497 927da1c00 replica ok -- All is well. ========= iteration 22 -- 22 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 17:05:58 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.12 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 18.4 tps, lat 54.222 ms stddev 45.291 progress: 10.0 s, 39.2 tps, lat 25.414 ms stddev 19.021 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 289 latency average = 34.746 ms latency stddev = 32.909 ms tps = 28.767231 (including connections establishing) tps = 28.780133 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 289 f2f4f313c d76638695 d8d57c12f dcbcdc2d2 master 6973 a,b,t,h: 100000 1 10 289 f2f4f313c d76638695 d8d57c12f dcbcdc2d2 replica ok -- All is well. ========= iteration 23 -- 23 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 17:06:17 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.13 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 55.4 tps, lat 18.036 ms stddev 17.304 progress: 10.0 s, 73.4 tps, lat 13.609 ms stddev 6.664 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 645 latency average = 15.508 ms latency stddev = 12.597 ms tps = 64.463976 (including connections establishing) tps = 64.483565 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 645 1de762376 5f0bfa0ac 487247169 7afb13eee master 6973 a,b,t,h: 100000 0 0 0 30dc896d4 d41d8cd98 d41d8cd98 d41d8cd98 replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 645 1de762376 5f0bfa0ac 487247169 7afb13eee master 6973 a,b,t,h: 100000 0 0 0 30dc896d4 d41d8cd98 d41d8cd98 d41d8cd98 replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 645 1de762376 5f0bfa0ac 487247169 7afb13eee master 6973 a,b,t,h: 100000 1 10 645 30dc896d4 5f0bfa0ac 487247169 7afb13eee replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 645 1de762376 5f0bfa0ac 487247169 7afb13eee master 6973 a,b,t,h: 100000 1 10 645 37c5a1453 5f0bfa0ac 487247169 7afb13eee replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 645 1de762376 5f0bfa0ac 487247169 7afb13eee master 6973 a,b,t,h: 100000 1 10 645 1de762376 5f0bfa0ac 487247169 7afb13eee replica ok -- All is well. ========= iteration 24 -- 24 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 17:06:59 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.13 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 40.0 tps, lat 24.954 ms stddev 22.448 progress: 10.0 s, 75.2 tps, lat 13.251 ms stddev 5.810 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 577 latency average = 17.347 ms latency stddev = 15.108 ms tps = 57.615325 (including connections establishing) tps = 57.646522 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 577 a6b83b046 4b26536ff 8330978d7 04d6d9677 master 6973 a,b,t,h: 100000 1 10 577 8e7207b4d 838ecc069 2d48ce063 04d6d9677 replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 577 a6b83b046 4b26536ff 8330978d7 04d6d9677 master 6973 a,b,t,h: 100000 1 10 577 ce340f3a5 4cd1e8573 a143fad9b 04d6d9677 replica NOK -- wait another 5s... 6972 a,b,t,h: 100000 1 10 577 a6b83b046 4b26536ff 8330978d7 04d6d9677 master 6973 a,b,t,h: 100000 1 10 577 a6b83b046 4b26536ff 8330978d7 04d6d9677 replica ok -- All is well. ========= iteration 25 -- 25 of 25 ========= -- scale 1 clients 1 INIT_WAIT 0 CLEAN_ONLY= ============================================================================ -- 20170222 17:07:30 -- scale 1 clients 1 INIT_WAIT 0 -- sub_count -ne 0 : deleting sub1 pub_count -ne 0 - deleting pub1 pub_count 0 pub_repl_slot_count 0 sub_count 0 sub_repl_slot_count 0 creating tables... 100000 of 100000 tuples (100%) done (elapsed 0.12 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972' publication pub1 with (disabled); alter subscription sub1 enable; -- pgbench -c 1 -T 10 -P 5 -n progress: 5.0 s, 27.2 tps, lat 36.671 ms stddev 24.266 progress: 10.0 s, 34.0 tps, lat 29.441 ms stddev 13.983 transaction type: scaling factor: 1 query mode: simple number of clients: 1 number of threads: 1 duration: 10 s number of transactions actually processed: 307 latency average = 32.626 ms latency stddev = 19.551 ms tps = 30.634663 (including connections establishing) tps = 30.650151 (excluding connections establishing) -- waiting 4s... (scale * 4) 6972 a,b,t,h: 100000 1 10 307 335760808 5ebd5ffe8 ef77b0332 85ec7bc33 master 6973 a,b,t,h: 100000 1 10 307 335760808 5ebd5ffe8 ef77b0332 85ec7bc33 replica ok -- All is well.