out_20170509_1635.txt
application/x-elc
(first iteration skipped; unrelated pilot error i.e., stupid mistake in startup harness) ========= iteration 2 -- 2 of 5 ========= ============================================================================ -- scale 25 clients 64 duration 900 CLEAN_ONLY= ============================================================================ -- hostname: kwetal -- time: 2017.05.09 16:35:21 -- timestamp: 20170509_1635 -- master_start_time 2017-05-09 16:35:16.017338+02 replica_start_time 2017-05-09 16:35:16.009379+02 -- master patch-md5 [a7eae7cc166cc96c1928b273342c1faa] -- replica patch-md5 [a7eae7cc166cc96c1928b273342c1faa] (ok) -- synchronous_commit, master [on] replica [on] -- master_assert [on] replica_assert [on] -- self md5 cf36e721a9d65e232067e021de0c3341 ./pgbench_derail2.sh -- port sb wm ecs mwm mrs mwp mlrw mws wst da 6972 128MB 4MB 4GB 64MB 10 12 10 14 1min on 2129db4c7 -- port sb wm ecs mwm mrs mwp mlrw mws wst da 6973 128MB 4MB 4GB 64MB 10 12 10 14 1min on add307a99 clean-at-start-call creating tables... 2500000 of 2500000 tuples (100%) done (elapsed 3.00 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972 application_name=derail2' publication pub1 with (disabled); alter subscription sub1 enable; port | pg_stat_replication | pid | wal | replay_loc | diff | ?column? | state | app | sync_state 6972 | pg_stat_replication | 84839 | F/FFD300E0 | | | | catchup | derail2 | async -- pgbench -c 64 -j 8 -T 900 -P 180 -n -- scale 25 progress: 180.0 s, 3139.0 tps, lat 20.004 ms stddev 162.471 progress: 360.0 s, 2012.0 tps, lat 32.400 ms stddev 219.864 progress: 540.0 s, 2517.1 tps, lat 25.176 ms stddev 257.433 progress: 720.0 s, 2489.1 tps, lat 25.971 ms stddev 196.469 progress: 900.0 s, 2547.9 tps, lat 25.015 ms stddev 198.344 transaction type: <builtin: TPC-B (sort of)> scaling factor: 25 query mode: simple number of clients: 64 number of threads: 8 duration: 900 s number of transactions actually processed: 2286962 latency average = 25.201 ms latency stddev = 206.938 ms tps = 2539.247505 (including connections establishing) tps = 2539.253557 (excluding connections establishing) port | pg_stat_replication | pid | wal | replay_loc | diff | ?column? | state | app | sync_state 6972 | pg_stat_replication | 84839 | 12/962FAAD0 | 12/1F0236A0 | 1999467568 | f | streaming | derail2 | async 2017.05.09 16:50:27 -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 2286962 d4922a4b7 f0c40ba6e a953e0dfb af21c43b9 master 6973 a,b,t,h: 2500000 25 250 1980409 574e601b2 baabf90f1 3da600bb6 9b7dbd839 replica NOK bd6270959 2017.05.09 16:51:37 port | pg_stat_replication | pid | wal | replay_loc | diff | ?column? | state | app | sync_state 6972 | pg_stat_replication | 84839 | 12/AC06F070 | 12/419C9B40 | 1785353520 | f | streaming | derail2 | async -- wait another 15 s (total 0 s) (unchanged 0) -- getting md5 (cb) 2017.05.09 16:51:52 2017.05.09 16:52:27 6972 a,b,t,h: 2500000 25 250 2286962 d4922a4b7 f0c40ba6e a953e0dfb af21c43b9 master 6973 a,b,t,h: 2500000 25 250 2126520 ad44add0c 69ecc67ce a087130d7 ea9573df5 replica NOK 4c788e355 port | pg_stat_replication | pid | wal | replay_loc | diff | ?column? | state | app | sync_state 6972 | pg_stat_replication | 84839 | 12/ADE88880 | 12/6B0127C0 | 1122459840 | f | streaming | derail2 | async -- wait another 15 s (total 15 s) (unchanged 0) -- getting md5 (cb) 2017.05.09 16:52:42 2017.05.09 16:53:23 6972 a,b,t,h: 2500000 25 250 2286962 d4922a4b7 f0c40ba6e a953e0dfb af21c43b9 master 6973 a,b,t,h: 2500000 25 250 2286962 a3920c55c f0c40ba6e a953e0dfb af21c43b9 replica NOK 80cc51b5e port | pg_stat_replication | pid | wal | replay_loc | diff | ?column? | state | app | sync_state 6972 | pg_stat_replication | 84839 | 12/B0562000 | 12/B0561448 | 3000 | f | streaming | derail2 | async -- wait another 15 s (total 30 s) (unchanged 0) -- getting md5 (cb) 2017.05.09 16:53:38 2017.05.09 16:54:00 6972 a,b,t,h: 2500000 25 250 2286962 d4922a4b7 f0c40ba6e a953e0dfb af21c43b9 master 6973 a,b,t,h: 2500000 25 250 2286962 d4922a4b7 f0c40ba6e a953e0dfb af21c43b9 replica ok ab1ae317d port | pg_stat_replication | pid | wal | replay_loc | diff | ?column? | state | app | sync_state 6972 | pg_stat_replication | 84839 | 12/B2838000 | 12/B2837020 | 4064 | f | streaming | derail2 | async -- All is well. -- 45 seconds total. scale 25 clients 64 -T 900 -- waiting 10s, then end-cleaning clean-at-end-call waiting for server to shut down.... done server stopped waiting for server to shut down.... done server stopped 2017-05-09 16:54:13.843 CEST 96502 LOG: listening on IPv6 address "::1", port 6973 2017-05-09 16:54:13.843 CEST 96500 LOG: listening on IPv6 address "::1", port 6972 2017-05-09 16:54:13.843 CEST 96502 LOG: listening on IPv4 address "127.0.0.1", port 6973 2017-05-09 16:54:13.843 CEST 96500 LOG: listening on IPv4 address "127.0.0.1", port 6972 2017-05-09 16:54:13.851 CEST 96500 LOG: listening on Unix socket "/tmp/.s.PGSQL.6972" 2017-05-09 16:54:13.851 CEST 96502 LOG: listening on Unix socket "/tmp/.s.PGSQL.6973" 2017-05-09 16:54:13.859 CEST 96500 LOG: redirecting log output to logging collector process 2017-05-09 16:54:13.859 CEST 96500 HINT: Future log output will appear in directory "/var/data1/pg_stuff/pg_installations/pgsql.logical_replication". 2017-05-09 16:54:13.859 CEST 96502 LOG: redirecting log output to logging collector process 2017-05-09 16:54:13.859 CEST 96502 HINT: Future log output will appear in directory "/var/data1/pg_stuff/pg_installations/pgsql.logical_replication2". ========= iteration 3 -- 3 of 5 ========= ============================================================================ -- scale 25 clients 64 duration 900 CLEAN_ONLY= ============================================================================ -- hostname: kwetal -- time: 2017.05.09 16:54:18 -- timestamp: 20170509_1635 -- master_start_time 2017-05-09 16:54:13.859564+02 replica_start_time 2017-05-09 16:54:13.859569+02 -- master patch-md5 [a7eae7cc166cc96c1928b273342c1faa] -- replica patch-md5 [a7eae7cc166cc96c1928b273342c1faa] (ok) -- synchronous_commit, master [on] replica [on] -- master_assert [on] replica_assert [on] -- self md5 cf36e721a9d65e232067e021de0c3341 ./pgbench_derail2.sh -- port sb wm ecs mwm mrs mwp mlrw mws wst da 6972 128MB 4MB 4GB 64MB 10 12 10 14 1min on 2129db4c7 -- port sb wm ecs mwm mrs mwp mlrw mws wst da 6973 128MB 4MB 4GB 64MB 10 12 10 14 1min on add307a99 clean-at-start-call creating tables... 2500000 of 2500000 tuples (100%) done (elapsed 2.64 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972 application_name=derail2' publication pub1 with (disabled); alter subscription sub1 enable; port | pg_stat_replication | pid | wal | replay_loc | diff | ?column? | state | app | sync_state 6972 | pg_stat_replication | 96808 | 12/C6F96E80 | | | | catchup | derail2 | async -- pgbench -c 64 -j 8 -T 900 -P 180 -n -- scale 25 progress: 180.0 s, 2399.0 tps, lat 26.629 ms stddev 229.742 progress: 360.0 s, 2219.8 tps, lat 28.878 ms stddev 187.134 progress: 540.0 s, 1938.4 tps, lat 32.601 ms stddev 256.982 progress: 720.0 s, 2501.7 tps, lat 25.903 ms stddev 308.936 progress: 900.0 s, 1850.1 tps, lat 34.524 ms stddev 340.947 transaction type: <builtin: TPC-B (sort of)> scaling factor: 25 query mode: simple number of clients: 64 number of threads: 8 duration: 900 s number of transactions actually processed: 1963689 latency average = 29.336 ms latency stddev = 268.487 ms tps = 2181.532592 (including connections establishing) tps = 2181.537248 (excluding connections establishing) port | pg_stat_replication | pid | wal | replay_loc | diff | ?column? | state | app | sync_state 6972 | pg_stat_replication | 96808 | 14/FEB99A30 | 14/92016348 | 1824012008 | f | streaming | derail2 | async 2017.05.09 17:09:24 -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 1963689 1ff5f2f10 08a7330d0 247c7549a 340d04912 master 6973 a,b,t,h: 2500000 25 250 1723170 8b4644cd0 58c60d6d0 a38f95c19 75a4e8ba1 replica NOK 847f36a00 2017.05.09 17:09:57 port | pg_stat_replication | pid | wal | replay_loc | diff | ?column? | state | app | sync_state 6972 | pg_stat_replication | 96808 | 15/222E9EF0 | 14/A42DB7F0 | 2113988352 | f | streaming | derail2 | async -- wait another 15 s (total 0 s) (unchanged 0) -- getting md5 (cb) 2017.05.09 17:10:12 2017.05.09 17:10:33 6972 a,b,t,h: 2500000 25 250 1963689 1ff5f2f10 08a7330d0 247c7549a 340d04912 master 6973 a,b,t,h: 2500000 25 250 1963689 24bcc2d37 a5b850cdf a2ea47908 dee0df3d1 replica NOK 959c40a06 port | pg_stat_replication | pid | wal | replay_loc | diff | ?column? | state | app | sync_state 6972 | pg_stat_replication | 96808 | 15/26C363C0 | 15/26C363C0 | 0 | t | streaming | derail2 | async -- wait another 15 s (total 15 s) (unchanged 0) -- getting md5 (cb) 2017.05.09 17:10:48 2017.05.09 17:11:03 6972 a,b,t,h: 2500000 25 250 1963689 1ff5f2f10 08a7330d0 247c7549a 340d04912 master 6973 a,b,t,h: 2500000 25 250 1963689 1ff5f2f10 08a7330d0 247c7549a 340d04912 replica ok 358c8b868 port | pg_stat_replication | pid | wal | replay_loc | diff | ?column? | state | app | sync_state 6972 | pg_stat_replication | 96808 | 15/274BC000 | 15/274BBF50 | 176 | f | streaming | derail2 | async -- All is well. -- 30 seconds total. scale 25 clients 64 -T 900 -- waiting 10s, then end-cleaning clean-at-end-call waiting for server to shut down.... done server stopped waiting for server to shut down.... done server stopped 2017-05-09 17:11:16.731 CEST 107147 LOG: listening on IPv6 address "::1", port 6973 2017-05-09 17:11:16.731 CEST 107147 LOG: listening on IPv4 address "127.0.0.1", port 6973 2017-05-09 17:11:16.740 CEST 107147 LOG: listening on Unix socket "/tmp/.s.PGSQL.6973" 2017-05-09 17:11:16.740 CEST 107145 LOG: listening on IPv6 address "::1", port 6972 2017-05-09 17:11:16.740 CEST 107145 LOG: listening on IPv4 address "127.0.0.1", port 6972 2017-05-09 17:11:16.741 CEST 107145 LOG: listening on Unix socket "/tmp/.s.PGSQL.6972" 2017-05-09 17:11:16.746 CEST 107147 LOG: redirecting log output to logging collector process 2017-05-09 17:11:16.746 CEST 107147 HINT: Future log output will appear in directory "/var/data1/pg_stuff/pg_installations/pgsql.logical_replication2". 2017-05-09 17:11:16.754 CEST 107145 LOG: redirecting log output to logging collector process 2017-05-09 17:11:16.754 CEST 107145 HINT: Future log output will appear in directory "/var/data1/pg_stuff/pg_installations/pgsql.logical_replication". ========= iteration 4 -- 4 of 5 ========= ============================================================================ -- scale 25 clients 64 duration 900 CLEAN_ONLY= ============================================================================ -- hostname: kwetal -- time: 2017.05.09 17:11:21 -- timestamp: 20170509_1635 -- master_start_time 2017-05-09 17:11:16.754805+02 replica_start_time 2017-05-09 17:11:16.747043+02 -- master patch-md5 [a7eae7cc166cc96c1928b273342c1faa] -- replica patch-md5 [a7eae7cc166cc96c1928b273342c1faa] (ok) -- synchronous_commit, master [on] replica [on] -- master_assert [on] replica_assert [on] -- self md5 cf36e721a9d65e232067e021de0c3341 ./pgbench_derail2.sh -- port sb wm ecs mwm mrs mwp mlrw mws wst da 6972 128MB 4MB 4GB 64MB 10 12 10 14 1min on 2129db4c7 -- port sb wm ecs mwm mrs mwp mlrw mws wst da 6973 128MB 4MB 4GB 64MB 10 12 10 14 1min on add307a99 clean-at-start-call creating tables... 2500000 of 2500000 tuples (100%) done (elapsed 2.47 s, remaining 0.00 s) vacuum... set primary keys... done. create publication pub1 for all tables; create subscription sub1 connection 'port=6972 application_name=derail2' publication pub1 with (disabled); alter subscription sub1 enable; port | pg_stat_replication | pid | wal | replay_loc | diff | ?column? | state | app | sync_state 6972 | pg_stat_replication | 107455 | 15/3AD00E78 | | | | catchup | derail2 | async -- pgbench -c 64 -j 8 -T 900 -P 180 -n -- scale 25 progress: 180.0 s, 4185.6 tps, lat 14.921 ms stddev 233.554 progress: 360.0 s, 2646.0 tps, lat 23.566 ms stddev 162.072 progress: 540.0 s, 5097.9 tps, lat 13.157 ms stddev 138.023 progress: 720.0 s, 4758.7 tps, lat 13.473 ms stddev 224.509 progress: 900.0 s, 5214.8 tps, lat 12.273 ms stddev 86.547 transaction type: <builtin: TPC-B (sort of)> scaling factor: 25 query mode: simple number of clients: 64 number of threads: 8 duration: 900 s number of transactions actually processed: 3942573 latency average = 14.610 ms latency stddev = 175.434 ms tps = 4380.328901 (including connections establishing) tps = 4380.338364 (excluding connections establishing) port | pg_stat_replication | pid | wal | replay_loc | diff | ?column? | state | app | sync_state 6972 | pg_stat_replication | 108349 | 19/8FBCC248 | | | | startup | derail2 | async 6972 | pg_stat_replication | 108351 | 19/8FBCC248 | | | | startup | derail2 | async 2017.05.09 17:26:27 -- getting md5 (cb) 6972 a,b,t,h: 2500000 25 250 3942573 fc666e226 7a5517471 b4ec4a6ca 8408a6a08 master 6973 a,b,t,h: 2500000 25 0 0 71b45b287 cd8371c36 d41d8cd98 d41d8cd98 replica NOK 430faedd2 2017.05.09 17:26:48 port | pg_stat_replication | pid | wal | replay_loc | diff | ?column? | state | app | sync_state 6972 | pg_stat_replication | 108349 | 19/AB000000 | | | | startup | derail2 | async 6972 | pg_stat_replication | 108351 | 19/AB000000 | | | | startup | derail2 | async -- wait another 15 s (total 0 s) (unchanged 0) -- getting md5 (cb) 2017.05.09 17:27:03 2017.05.09 17:27:17 6972 a,b,t,h: 2500000 25 250 3942573 fc666e226 7a5517471 b4ec4a6ca 8408a6a08 master 6973 a,b,t,h: 2500000 25 0 0 71b45b287 cd8371c36 d41d8cd98 d41d8cd98 replica NOK 430faedd2 port | pg_stat_replication | pid | wal | replay_loc | diff | ?column? | state | app | sync_state 6972 | pg_stat_replication | 108349 | 19/AD0D0248 | | | | startup | derail2 | async 6972 | pg_stat_replication | 108351 | 19/AD0D0248 | | | | startup | derail2 | async [...] [removed several (18x) repeating paragraphs] -- wait another 15 s (total 285 s) (unchanged 19) -- getting md5 (cb) 2017.05.09 17:36:18 2017.05.09 17:36:32 6972 a,b,t,h: 2500000 25 250 3942573 fc666e226 7a5517471 b4ec4a6ca 8408a6a08 master 6973 a,b,t,h: 2500000 25 0 0 71b45b287 cd8371c36 d41d8cd98 d41d8cd98 replica NOK 430faedd2 port | pg_stat_replication | pid | wal | replay_loc | diff | ?column? | state | app | sync_state 6972 | pg_stat_replication | 108349 | 19/C3A1CD00 | | | | startup | derail2 | async 6972 | pg_stat_replication | 108351 | 19/C3A1CD00 | | | | startup | derail2 | async -- wait another 15 s (total 300 s) (unchanged 20) -- getting md5 (cb) 2017.05.09 17:36:47 2017.05.09 17:37:01 6972 a,b,t,h: 2500000 25 250 3942573 fc666e226 7a5517471 b4ec4a6ca 8408a6a08 master 6973 a,b,t,h: 2500000 25 0 0 71b45b287 cd8371c36 d41d8cd98 d41d8cd98 replica NOK 430faedd2 -- Not good, but breaking out of wait (21 times no change)