========= iteration 1 -- 1 of 10 ========= ============================================================================ -- scale 25 clients 64 duration 300 CLEAN_ONLY= ============================================================================ -- hostname: barzoi -- timestamp: 20170309_1021 -- master_start_time 2017-03-08 12:04:02.127127+01 replica_start_time 2017-03-08 12:04:02.12713+01 -- master patch-md5 [59c92165d4a328d68450ef0e922c0a42] -- replica patch-md5 [59c92165d4a328d68450ef0e922c0a42] (ok) -- synchronous_commit, master [on] replica [off] -- master_assert [on] replica_assert [on] -- self md5 87554cfed7cda67ad292b6481e1b8b41 ./pgbench_derail2.sh clean-at-start-call creating tables... 1699900 of 2500000 tuples (67%) done (elapsed 5.19 s, remaining 2.44 s) 2500000 of 2500000 tuples (100%) done (elapsed 7.51 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 64 -j 8 -T 300 -P 60 -n -- scale 25 progress: 60.0 s, 134.4 tps, lat 472.280 ms stddev 622.992 progress: 120.0 s, 26.4 tps, lat 2083.748 ms stddev 4356.546 progress: 180.0 s, 21.2 tps, lat 2977.751 ms stddev 4767.332 progress: 240.0 s, 13.5 tps, lat 5230.657 ms stddev 7029.718 progress: 300.0 s, 42.4 tps, lat 1555.645 ms stddev 1733.152 transaction type: scaling factor: 25 query mode: simple number of clients: 64 number of threads: 8 duration: 300 s number of transactions actually processed: 14336 latency average = 1342.222 ms latency stddev = 3043.759 ms tps = 47.383887 (including connections establishing) tps = 47.385513 (excluding connections establishing) -- waiting 0s... (always) 2017.03.09 10:27:56 -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 14336 ee0f7bfd9 960d7d79c 3e8af1e9e cd2bd0395 master 6973 a,b,t,h: 2500000 25 250 14336 ee0f7bfd9 960d7d79c 3e8af1e9e cd2bd0395 replica ok 578113f12 2017.03.09 10:29:18 -- All is well. -- 0 seconds total. scale 25 clients 64 -T 300 -- waiting 20s, then end-cleaning clean-at-end-call sub_count -ne 0 : deleting sub1 (plain) ERROR: could not drop the replication slot "sub1" on publisher DETAIL: The error was: ERROR: replication slot "sub1" is active for PID 10569 sub_count -ne 0 : deleting sub1 (nodrop) pub_count -ne 0 - deleting pub1 pub_repl_slot_count -ne 0 - deleting (sub1) ERROR: replication slot "sub1" is active for PID 10569 pub_count 0 pub_repl_slot_count 1 sub_count 0 sub_repl_slot_count 0 -- imperfect cleanup, pg_waldump to unclean.20170309_1021.txt.bz2, waiting 60 s, then exit -- testset.sh: waiting 10s... ========= iteration 2 -- 2 of 10 ========= ============================================================================ -- scale 25 clients 64 duration 300 CLEAN_ONLY= ============================================================================ -- hostname: barzoi -- timestamp: 20170309_1021 -- master_start_time 2017-03-08 12:04:02.127127+01 replica_start_time 2017-03-08 12:04:02.12713+01 -- master patch-md5 [59c92165d4a328d68450ef0e922c0a42] -- replica patch-md5 [59c92165d4a328d68450ef0e922c0a42] (ok) -- synchronous_commit, master [on] replica [off] -- master_assert [on] replica_assert [on] -- self md5 87554cfed7cda67ad292b6481e1b8b41 ./pgbench_derail2.sh clean-at-start-call pub_repl_slot_count -ne 0 - deleting (sub1) pg_drop_replication_slot -------------------------- (1 row) creating tables... 1596800 of 2500000 tuples (63%) done (elapsed 5.09 s, remaining 2.88 s) 2500000 of 2500000 tuples (100%) done (elapsed 7.88 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 64 -j 8 -T 300 -P 60 -n -- scale 25 progress: 60.0 s, 129.0 tps, lat 493.130 ms stddev 635.654 progress: 120.0 s, 34.0 tps, lat 1679.787 ms stddev 3808.253 progress: 180.0 s, 25.6 tps, lat 2773.775 ms stddev 4709.481 progress: 240.0 s, 26.7 tps, lat 2119.122 ms stddev 3447.122 progress: 300.0 s, 12.3 tps, lat 5411.023 ms stddev 6659.422 transaction type: scaling factor: 25 query mode: simple number of clients: 64 number of threads: 8 duration: 300 s number of transactions actually processed: 13718 latency average = 1415.080 ms latency stddev = 3258.969 ms tps = 44.813091 (including connections establishing) tps = 44.814631 (excluding connections establishing) -- waiting 0s... (always) 2017.03.09 10:37:46 -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa 2017.03.09 10:38:49 -- wait another 5 s (total 0 s) (unchanged 0) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 5 s) (unchanged 1) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 10 s) (unchanged 2) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 15 s) (unchanged 3) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 20 s) (unchanged 4) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa table pg_subscription_rel; table pg_replication_origin_status; srsubid | srrelid | srsubstate | srsublsn ---------+---------+------------+------------- 37231 | 37203 | r | 27/624E1408 37231 | 37200 | r | 27/62758800 37231 | 37206 | r | 27/62860B18 37231 | 37211 | r | 27/629EE990 (4 rows) local_id | external_id | remote_lsn | local_lsn ----------+-------------+-------------+------------- 1 | pg_37231 | 27/62C09A50 | 48/CA986BF8 (1 row) table pg_replication_slots; slot_name | plugin | slot_type | datoid | database | temporary | active | active_pid | xmin | catalog_xmin | restart_lsn | confirmed_flush_lsn -----------+----------+-----------+--------+----------+-----------+--------+------------+------+--------------+-------------+--------------------- sub1 | pgoutput | logical | 16384 | testdb | f | f | | | 5692123 | 27/62AEBDC8 | 27/62C09A50 (1 row) -- parsing [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000069 1] -- walf [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000069] -- bz2f [waldump.20170309_1021_1039.1.5.000000010000002700000069.txt.bz2] -- lines 2664 -- (before) pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000069 -- file: /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000069 -- 2664 lines -- pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000069 2>&1 | bzip2 > waldump.20170309_1021_1039.1.5.000000010000002700000069.txt.bz2 -- parsing [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/0000000100000048000000DD 2] -- walf [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/0000000100000048000000DD] -- bz2f [waldump.20170309_1021_1039.2.5.000000010000002700000069.txt.bz2] -- lines 7497 -- (before) pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/0000000100000048000000DD -- file: /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/0000000100000048000000DD -- 7497 lines -- pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/0000000100000048000000DD 2>&1 | bzip2 > waldump.20170309_1021_1039.2.5.000000010000002700000069.txt.bz2 -- wait another 5 s (total 25 s) (unchanged 5) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 30 s) (unchanged 6) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 35 s) (unchanged 7) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 40 s) (unchanged 8) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 45 s) (unchanged 9) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 50 s) (unchanged 10) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 55 s) (unchanged 11) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 60 s) (unchanged 12) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 65 s) (unchanged 13) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 70 s) (unchanged 14) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 75 s) (unchanged 15) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 80 s) (unchanged 16) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 85 s) (unchanged 17) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 90 s) (unchanged 18) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 95 s) (unchanged 19) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- wait another 5 s (total 100 s) (unchanged 20) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 13718 73599bbb1 302956aac 4bf2f7e03 0b5a112ec master 6973 a,b,t,h: 2500000 25 250 12674 b5fc0c15f 7b62045fe b710b85d1 4e5c8b3da replica NOK 22200d2fa -- Not good, but breaking out of wait (21 times no change) table pg_subscription_rel; table pg_replication_origin_status; srsubid | srrelid | srsubstate | srsublsn ---------+---------+------------+------------- 37231 | 37203 | r | 27/624E1408 37231 | 37200 | r | 27/62758800 37231 | 37206 | r | 27/62860B18 37231 | 37211 | r | 27/629EE990 (4 rows) local_id | external_id | remote_lsn | local_lsn ----------+-------------+-------------+------------- 1 | pg_37231 | 27/62C09A50 | 48/CA986BF8 (1 row) table pg_replication_slots; slot_name | plugin | slot_type | datoid | database | temporary | active | active_pid | xmin | catalog_xmin | restart_lsn | confirmed_flush_lsn -----------+----------+-----------+--------+----------+-----------+--------+------------+------+--------------+-------------+--------------------- sub1 | pgoutput | logical | 16384 | testdb | f | f | | | 5692123 | 27/62AEBDC8 | 27/62C09A50 (1 row) -- parsing [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000069 1] -- walf [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000069] -- bz2f [waldump.20170309_1021_1043.1.21.000000010000002700000069.txt.bz2] -- lines 2664 -- (before) pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000069 -- file: /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000069 -- 2664 lines -- pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000069 2>&1 | bzip2 > waldump.20170309_1021_1043.1.21.000000010000002700000069.txt.bz2 -- parsing [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/0000000100000048000000DD 2] -- walf [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/0000000100000048000000DD] -- bz2f [waldump.20170309_1021_1043.2.21.000000010000002700000069.txt.bz2] -- lines 12019 -- (before) pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/0000000100000048000000DD -- file: /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/0000000100000048000000DD -- 12019 lines -- pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/0000000100000048000000DD 2>&1 | bzip2 > waldump.20170309_1021_1043.2.21.000000010000002700000069.txt.bz2 -- (wait_total 105 s) -- waiting 20s, then end-cleaning clean-at-end-call sub_count -ne 0 : deleting sub1 (plain) sub_count -ne 0 : deleting sub1 (nodrop) pub_count -ne 0 - deleting pub1 -- testset.sh: waiting 10s... ========= iteration 3 -- 3 of 10 ========= ============================================================================ -- scale 25 clients 64 duration 300 CLEAN_ONLY= ============================================================================ -- hostname: barzoi -- timestamp: 20170309_1021 -- master_start_time 2017-03-08 12:04:02.127127+01 replica_start_time 2017-03-08 12:04:02.12713+01 -- master patch-md5 [59c92165d4a328d68450ef0e922c0a42] -- replica patch-md5 [59c92165d4a328d68450ef0e922c0a42] (ok) -- synchronous_commit, master [on] replica [off] -- master_assert [on] replica_assert [on] -- self md5 87554cfed7cda67ad292b6481e1b8b41 ./pgbench_derail2.sh clean-at-start-call creating tables... 1780100 of 2500000 tuples (71%) done (elapsed 5.17 s, remaining 2.09 s) 2500000 of 2500000 tuples (100%) done (elapsed 7.40 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 64 -j 8 -T 300 -P 60 -n -- scale 25 progress: 60.0 s, 128.6 tps, lat 492.297 ms stddev 636.199 progress: 120.0 s, 31.9 tps, lat 1623.134 ms stddev 3812.437 progress: 180.0 s, 14.6 tps, lat 5168.904 ms stddev 8687.071 progress: 240.0 s, 63.9 tps, lat 1015.973 ms stddev 1480.597 progress: 300.0 s, 85.5 tps, lat 675.831 ms stddev 1752.534 transaction type: scaling factor: 25 query mode: simple number of clients: 64 number of threads: 8 duration: 300 s number of transactions actually processed: 19545 latency average = 994.479 ms latency stddev = 2740.546 ms tps = 62.971798 (including connections establishing) tps = 62.973751 (excluding connections establishing) -- waiting 0s... (always) 2017.03.09 10:49:52 -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c 2017.03.09 10:51:00 -- wait another 5 s (total 0 s) (unchanged 0) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 5 s) (unchanged 1) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 10 s) (unchanged 2) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 15 s) (unchanged 3) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 20 s) (unchanged 4) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c table pg_subscription_rel; table pg_replication_origin_status; srsubid | srrelid | srsubstate | srsublsn ---------+---------+------------+------------- 37267 | 37239 | r | 27/7F2020D8 37267 | 37236 | r | 27/81222AD0 37267 | 37242 | r | 27/81834060 37267 | 37247 | s | 27/828EA980 (4 rows) local_id | external_id | remote_lsn | local_lsn ----------+-------------+-------------+------------ 1 | pg_37267 | 27/82661788 | 49/D12C0E8 (1 row) table pg_replication_slots; slot_name | plugin | slot_type | datoid | database | temporary | active | active_pid | xmin | catalog_xmin | restart_lsn | confirmed_flush_lsn -----------+----------+-----------+--------+----------+-----------+--------+------------+------+--------------+-------------+--------------------- sub1 | pgoutput | logical | 16384 | testdb | f | f | | | 5701209 | 27/816FDB30 | 27/82661788 (1 row) -- parsing [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000090 1] -- walf [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000090] -- bz2f [waldump.20170309_1021_1052.1.5.000000010000002700000090.txt.bz2] -- lines 500 -- (before) pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000090 -- file: /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000090 -- 500 lines -- pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000090 2>&1 | bzip2 > waldump.20170309_1021_1052.1.5.000000010000002700000090.txt.bz2 -- parsing [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000017 2] -- walf [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000017] -- bz2f [waldump.20170309_1021_1052.2.5.000000010000002700000090.txt.bz2] -- lines 446 -- (before) pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000017 -- file: /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000017 -- 446 lines -- pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000017 2>&1 | bzip2 > waldump.20170309_1021_1052.2.5.000000010000002700000090.txt.bz2 -- wait another 5 s (total 25 s) (unchanged 5) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 30 s) (unchanged 6) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 35 s) (unchanged 7) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 40 s) (unchanged 8) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 45 s) (unchanged 9) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 50 s) (unchanged 10) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 55 s) (unchanged 11) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 60 s) (unchanged 12) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 65 s) (unchanged 13) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 70 s) (unchanged 14) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 75 s) (unchanged 15) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 80 s) (unchanged 16) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 85 s) (unchanged 17) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 90 s) (unchanged 18) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 95 s) (unchanged 19) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- wait another 5 s (total 100 s) (unchanged 20) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 19545 271cec7ed d95d3475e 3091f5a92 383e94433 master 6973 a,b,t,h: 2500000 25 250 9349 e7c275071 5ff8fa276 a72875613 c7f4ae66f replica NOK aa90d9a4c -- Not good, but breaking out of wait (21 times no change) table pg_subscription_rel; table pg_replication_origin_status; srsubid | srrelid | srsubstate | srsublsn ---------+---------+------------+------------- 37267 | 37239 | r | 27/7F2020D8 37267 | 37236 | r | 27/81222AD0 37267 | 37242 | r | 27/81834060 37267 | 37247 | s | 27/828EA980 (4 rows) local_id | external_id | remote_lsn | local_lsn ----------+-------------+-------------+------------ 1 | pg_37267 | 27/82661788 | 49/D12C0E8 (1 row) table pg_replication_slots; slot_name | plugin | slot_type | datoid | database | temporary | active | active_pid | xmin | catalog_xmin | restart_lsn | confirmed_flush_lsn -----------+----------+-----------+--------+----------+-----------+--------+------------+------+--------------+-------------+--------------------- sub1 | pgoutput | logical | 16384 | testdb | f | f | | | 5701209 | 27/816FDB30 | 27/82661788 (1 row) -- parsing [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000090 1] -- walf [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000090] -- bz2f [waldump.20170309_1021_1055.1.21.000000010000002700000090.txt.bz2] -- lines 503 -- (before) pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000090 -- file: /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000090 -- 503 lines -- pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/000000010000002700000090 2>&1 | bzip2 > waldump.20170309_1021_1055.1.21.000000010000002700000090.txt.bz2 -- parsing [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000017 2] -- walf [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000017] -- bz2f [waldump.20170309_1021_1055.2.21.000000010000002700000090.txt.bz2] -- lines 687 -- (before) pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000017 -- file: /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000017 -- 687 lines -- pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000017 2>&1 | bzip2 > waldump.20170309_1021_1055.2.21.000000010000002700000090.txt.bz2 -- (wait_total 105 s) -- waiting 20s, then end-cleaning clean-at-end-call sub_count -ne 0 : deleting sub1 (plain) sub_count -ne 0 : deleting sub1 (nodrop) pub_count -ne 0 - deleting pub1 -- testset.sh: waiting 10s... ========= iteration 4 -- 4 of 10 ========= ============================================================================ -- scale 25 clients 64 duration 300 CLEAN_ONLY= ============================================================================ -- hostname: barzoi -- timestamp: 20170309_1021 -- master_start_time 2017-03-08 12:04:02.127127+01 replica_start_time 2017-03-08 12:04:02.12713+01 -- master patch-md5 [59c92165d4a328d68450ef0e922c0a42] -- replica patch-md5 [59c92165d4a328d68450ef0e922c0a42] (ok) -- synchronous_commit, master [on] replica [off] -- master_assert [on] replica_assert [on] -- self md5 87554cfed7cda67ad292b6481e1b8b41 ./pgbench_derail2.sh clean-at-start-call creating tables... 1701200 of 2500000 tuples (68%) done (elapsed 5.00 s, remaining 2.35 s) 2500000 of 2500000 tuples (100%) done (elapsed 7.98 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 64 -j 8 -T 300 -P 60 -n -- scale 25 progress: 60.0 s, 152.7 tps, lat 411.175 ms stddev 554.315 progress: 120.0 s, 34.8 tps, lat 1770.342 ms stddev 3061.939 progress: 180.0 s, 9.3 tps, lat 6638.393 ms stddev 5392.463 progress: 240.0 s, 49.1 tps, lat 1268.013 ms stddev 2752.765 progress: 300.0 s, 15.5 tps, lat 4434.394 ms stddev 5996.309 transaction type: scaling factor: 25 query mode: simple number of clients: 64 number of threads: 8 duration: 300 s number of transactions actually processed: 15745 latency average = 1221.427 ms latency stddev = 2851.259 ms tps = 52.289500 (including connections establishing) tps = 52.291391 (excluding connections establishing) -- waiting 0s... (always) 2017.03.09 11:02:03 -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 15745 9337c5be5 bf71d5c15 15350693f a92a36f7e master 6973 a,b,t,h: 2500000 25 250 15745 9337c5be5 bf71d5c15 15350693f a92a36f7e replica ok 61d31684c 2017.03.09 11:04:07 -- All is well. -- 0 seconds total. scale 25 clients 64 -T 300 -- waiting 20s, then end-cleaning clean-at-end-call sub_count -ne 0 : deleting sub1 (plain) sub_count -ne 0 : deleting sub1 (nodrop) pub_count -ne 0 - deleting pub1 -- testset.sh: waiting 10s... ========= iteration 5 -- 5 of 10 ========= ============================================================================ -- scale 25 clients 64 duration 300 CLEAN_ONLY= ============================================================================ -- hostname: barzoi -- timestamp: 20170309_1021 -- master_start_time 2017-03-08 12:04:02.127127+01 replica_start_time 2017-03-08 12:04:02.12713+01 -- master patch-md5 [59c92165d4a328d68450ef0e922c0a42] -- replica patch-md5 [59c92165d4a328d68450ef0e922c0a42] (ok) -- synchronous_commit, master [on] replica [off] -- master_assert [on] replica_assert [on] -- self md5 87554cfed7cda67ad292b6481e1b8b41 ./pgbench_derail2.sh clean-at-start-call creating tables... 1635100 of 2500000 tuples (65%) done (elapsed 5.00 s, remaining 2.64 s) 2500000 of 2500000 tuples (100%) done (elapsed 7.34 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 64 -j 8 -T 300 -P 60 -n -- scale 25 progress: 60.0 s, 99.9 tps, lat 633.458 ms stddev 811.704 progress: 120.0 s, 57.3 tps, lat 969.062 ms stddev 2178.241 progress: 180.0 s, 32.8 tps, lat 2181.112 ms stddev 4917.504 progress: 240.0 s, 58.4 tps, lat 1103.141 ms stddev 2466.176 progress: 300.0 s, 42.8 tps, lat 1456.959 ms stddev 3386.565 transaction type: scaling factor: 25 query mode: simple number of clients: 64 number of threads: 8 duration: 300 s number of transactions actually processed: 17545 latency average = 1098.486 ms latency stddev = 2654.628 ms tps = 57.833132 (including connections establishing) tps = 57.835168 (excluding connections establishing) -- waiting 0s... (always) 2017.03.09 11:10:52 -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 2017.03.09 11:11:58 -- wait another 5 s (total 0 s) (unchanged 0) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 5 s) (unchanged 1) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 10 s) (unchanged 2) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 15 s) (unchanged 3) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 20 s) (unchanged 4) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 table pg_subscription_rel; table pg_replication_origin_status; srsubid | srrelid | srsubstate | srsublsn ---------+---------+------------+------------- 37340 | 37312 | r | 27/D1925440 37340 | 37309 | r | 27/D3B540B0 37340 | 37315 | r | 27/D45B3928 37340 | 37320 | r | 27/D5588F40 (4 rows) local_id | external_id | remote_lsn | local_lsn ----------+-------------+-------------+------------- 1 | pg_37340 | 27/D66818D8 | 49/8C1622A0 (1 row) table pg_replication_slots; slot_name | plugin | slot_type | datoid | database | temporary | active | active_pid | xmin | catalog_xmin | restart_lsn | confirmed_flush_lsn -----------+----------+-----------+--------+----------+-----------+--------+------------+------+--------------+-------------+--------------------- sub1 | pgoutput | logical | 16384 | testdb | f | f | | | 5737826 | 27/D533F9B0 | 27/D66818D8 (1 row) -- parsing [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/0000000100000027000000E2 1] -- walf [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/0000000100000027000000E2] -- bz2f [waldump.20170309_1021_1113.1.5.0000000100000027000000E2.txt.bz2] -- lines 2868 -- (before) pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/0000000100000027000000E2 -- file: /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/0000000100000027000000E2 -- 2868 lines -- pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/0000000100000027000000E2 2>&1 | bzip2 > waldump.20170309_1021_1113.1.5.0000000100000027000000E2.txt.bz2 -- parsing [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000098 2] -- walf [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000098] -- bz2f [waldump.20170309_1021_1113.2.5.0000000100000027000000E2.txt.bz2] -- lines 696 -- (before) pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000098 -- file: /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000098 -- 696 lines -- pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000098 2>&1 | bzip2 > waldump.20170309_1021_1113.2.5.0000000100000027000000E2.txt.bz2 -- wait another 5 s (total 25 s) (unchanged 5) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 30 s) (unchanged 6) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 35 s) (unchanged 7) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 40 s) (unchanged 8) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 45 s) (unchanged 9) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 50 s) (unchanged 10) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 55 s) (unchanged 11) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 60 s) (unchanged 12) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 65 s) (unchanged 13) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 70 s) (unchanged 14) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 75 s) (unchanged 15) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 80 s) (unchanged 16) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 85 s) (unchanged 17) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 90 s) (unchanged 18) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 95 s) (unchanged 19) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- wait another 5 s (total 100 s) (unchanged 20) -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 17545 2d620e07c 592b6ad24 636bd4ee3 4b44672dd master 6973 a,b,t,h: 2500000 25 250 9293 6ba849c83 c2a81c550 922a39571 714d7593b replica NOK d574a9304 -- Not good, but breaking out of wait (21 times no change) table pg_subscription_rel; table pg_replication_origin_status; srsubid | srrelid | srsubstate | srsublsn ---------+---------+------------+------------- 37340 | 37312 | r | 27/D1925440 37340 | 37309 | r | 27/D3B540B0 37340 | 37315 | r | 27/D45B3928 37340 | 37320 | r | 27/D5588F40 (4 rows) local_id | external_id | remote_lsn | local_lsn ----------+-------------+-------------+------------- 1 | pg_37340 | 27/D66818D8 | 49/8C1622A0 (1 row) table pg_replication_slots; slot_name | plugin | slot_type | datoid | database | temporary | active | active_pid | xmin | catalog_xmin | restart_lsn | confirmed_flush_lsn -----------+----------+-----------+--------+----------+-----------+--------+------------+------+--------------+-------------+--------------------- sub1 | pgoutput | logical | 16384 | testdb | f | f | | | 5737826 | 27/D533F9B0 | 27/D66818D8 (1 row) -- parsing [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/0000000100000027000000E2 1] -- walf [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/0000000100000027000000E2] -- bz2f [waldump.20170309_1021_1116.1.21.0000000100000027000000E2.txt.bz2] -- lines 2868 -- (before) pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/0000000100000027000000E2 -- file: /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/0000000100000027000000E2 -- 2868 lines -- pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication/data/pg_wal/0000000100000027000000E2 2>&1 | bzip2 > waldump.20170309_1021_1116.1.21.0000000100000027000000E2.txt.bz2 -- parsing [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000098 2] -- walf [/home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000098] -- bz2f [waldump.20170309_1021_1116.2.21.0000000100000027000000E2.txt.bz2] -- lines 1009 -- (before) pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000098 -- file: /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000098 -- 1009 lines -- pg_waldump /home/aardvark/pg_stuff/pg_installations/pgsql.logical_replication2/data/pg_wal/000000010000004900000098 2>&1 | bzip2 > waldump.20170309_1021_1116.2.21.0000000100000027000000E2.txt.bz2 -- (wait_total 105 s) -- waiting 20s, then end-cleaning clean-at-end-call sub_count -ne 0 : deleting sub1 (plain) sub_count -ne 0 : deleting sub1 (nodrop) pub_count -ne 0 - deleting pub1 -- testset.sh: waiting 10s... ========= iteration 6 -- 6 of 10 ========= ============================================================================ -- scale 25 clients 64 duration 300 CLEAN_ONLY= ============================================================================ -- hostname: barzoi -- timestamp: 20170309_1021 -- master_start_time 2017-03-08 12:04:02.127127+01 replica_start_time 2017-03-08 12:04:02.12713+01 -- master patch-md5 [59c92165d4a328d68450ef0e922c0a42] -- replica patch-md5 [59c92165d4a328d68450ef0e922c0a42] (ok) -- synchronous_commit, master [on] replica [off] -- master_assert [on] replica_assert [on] -- self md5 87554cfed7cda67ad292b6481e1b8b41 ./pgbench_derail2.sh clean-at-start-call creating tables... 1651800 of 2500000 tuples (66%) done (elapsed 5.00 s, remaining 2.57 s) 2500000 of 2500000 tuples (100%) done (elapsed 7.42 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 64 -j 8 -T 300 -P 60 -n -- scale 25 progress: 60.0 s, 143.3 tps, lat 443.151 ms stddev 619.222 progress: 120.0 s, 21.3 tps, lat 2671.388 ms stddev 5356.946 progress: 180.0 s, 51.2 tps, lat 1252.638 ms stddev 2746.218 progress: 240.0 s, 7.1 tps, lat 8288.817 ms stddev 6335.279 progress: 300.0 s, 9.9 tps, lat 7078.697 ms stddev 8657.126 transaction type: scaling factor: 25 query mode: simple number of clients: 64 number of threads: 8 duration: 300 s number of transactions actually processed: 14030 latency average = 1381.823 ms latency stddev = 3593.944 ms tps = 45.248364 (including connections establishing) tps = 45.249744 (excluding connections establishing) -- waiting 0s... (always) 2017.03.09 11:23:16 -- getting md5 (cb)