Re: Postgres stucks in deadlock detection

On 14.04.2018 10:09, Юрий Соколов wrote:
> пт, 13 апр. 2018 г., 21:10 Andres Freund <andres(at)anarazel(dot)de
> <mailto:andres(at)anarazel(dot)de>>:
>
> Hi,
>
> On 2018-04-13 19:13:07 +0300, Konstantin Knizhnik wrote:
> > On 13.04.2018 18:41, Andres Freund wrote:
> > > On 2018-04-13 16:43:09 +0300, Konstantin Knizhnik wrote:
> > > > Updated patch is attached.
> > > > + /*
> > > > +  * Ensure that only one backend is checking for deadlock.
> > > > +  * Otherwise under high load cascade of deadlock timeout
> expirations can cause stuck of Postgres.
> > > > +  */
> > > > + if
> (!pg_atomic_test_set_flag(&ProcGlobal->activeDeadlockCheck))
> > > > + {
> > > > +  enable_timeout_after(DEADLOCK_TIMEOUT, DeadlockTimeout);
> > > > +         return;
> > > > + }
> > > > + inside_deadlock_check = true;
> > > I can't see that ever being accepted.  This means there's
> absolutely no
> > > bound for deadlock checks happening even under light
> concurrency, even
> > > if there's no contention for a large fraction of the time.
> >
> > It may cause problems only if
> > 1. There is large number of active sessions
> > 2. They perform deadlock-prone queries (so no attempts to avoid
> deadlocks at
> > application level)
> > 3. Deadlock timeout is set to be very small (10 msec?)
>
> That's just not true.
>
>
> > Otherwise either probability that all backends  once and once
> again are
> > trying to check deadlocks concurrently is very small (and can be
> even more
> > reduced by using random timeout for subsequent deadlock checks),
> either
> > system can not normally function in any case because large
> number of clients
> > fall into deadlock.
>
> Operating systems batch wakeups.
>
>
> > I completely agree that there are plenty of different
> approaches, but IMHO
> > the currently used strategy is the worst one, because it can
> stall system
> > even if there are not deadlocks at all.
>
>
> > I always think that deadlock is a programmer's error rather than
> normal
> > situation. May be it is wrong assumption
>
> It is.
>
>
> > So before implementing some complicated solution of the
> problem9too slow
> > deadlock detection), I think that first it is necessary to
> understand
> > whether there is such problem at al and under which workload it
> can happen.
>
> Sure. I'm not saying that you shouldn't experiment with a patch
> like the
> one you sent. What I am saying is that that can't be the actual
> solution
> that will be integrated.
>
>
> What about my version?
> at
> https://www.postgresql.org/message-id/flat/bac42052debbd66e8d5f786d8abe8db1(at)postgrespro(dot)ru
> It still performs deadlock detection every time, but it tries to
> detect it with shared lock first,
> and only if there is probability of real deadlock, it rechecks with
> exclusive lock.
>
> Although even shared lock leads to some stalleness for active
> transactions, but in the catastrophic situation, where many backends
> to check for inexisting deadlock at the same time, it greately reduce
> pause.

Unfortunately your patch doesn't help with inserts.
In most cases Postgres obtains exclusive partition locks: any
lock/unlock operation requires exclusive lock.
Shared locks of all partitions are used for collecting some information
or to perform recovery.

Below results of three different versions:

1. Vanilla Postgres:

[kk(at)hp06 knizhnik]$ pgbench -n -c 1000 -j 36 -T 100 -P 1 -f test.sql
postgres
progress: 1.0 s, 227.9 tps, lat 109.560 ms stddev 189.328
progress: 2.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 3.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 4.0 s, 53.0 tps, lat 1145.417 ms stddev 1607.484
progress: 5.0 s, 19.0 tps, lat 236.807 ms stddev 819.307
progress: 6.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 7.0 s, 2.0 tps, lat 6649.944 ms stddev 9.691
progress: 8.0 s, 60.0 tps, lat 2343.313 ms stddev 3335.967
progress: 9.0 s, 89.0 tps, lat 1813.495 ms stddev 3337.904
progress: 10.0 s, 99.1 tps, lat 2093.653 ms stddev 3758.468
progress: 11.0 s, 94.9 tps, lat 2424.560 ms stddev 4258.622
progress: 12.0 s, 79.0 tps, lat 2037.880 ms stddev 4152.258
progress: 13.0 s, 30.0 tps, lat 80.697 ms stddev 24.854
progress: 14.0 s, 2.0 tps, lat 71.642 ms stddev 0.022
progress: 15.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 16.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 17.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 18.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 19.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 20.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 21.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 22.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 23.0 s, 3.0 tps, lat 22396.463 ms stddev 1.964
progress: 24.0 s, 1.0 tps, lat 23667.927 ms stddev 0.001
progress: 25.0 s, 25.0 tps, lat 8862.603 ms stddev 11545.517
progress: 26.0 s, 27.0 tps, lat 6738.338 ms stddev 10984.215
progress: 27.0 s, 40.0 tps, lat 6656.893 ms stddev 11236.042
progress: 28.0 s, 49.0 tps, lat 10124.108 ms stddev 13042.391
progress: 29.0 s, 20.0 tps, lat 8638.022 ms stddev 12916.653
progress: 30.0 s, 45.0 tps, lat 9805.039 ms stddev 13624.253
progress: 31.0 s, 30.0 tps, lat 7151.608 ms stddev 12628.340
progress: 32.0 s, 48.0 tps, lat 9838.776 ms stddev 14316.187
progress: 33.0 s, 44.0 tps, lat 7479.878 ms stddev 13394.234
progress: 34.0 s, 55.0 tps, lat 8530.081 ms stddev 14327.334
progress: 35.0 s, 57.0 tps, lat 12054.371 ms stddev 15630.142
progress: 36.0 s, 17.0 tps, lat 8620.003 ms stddev 14896.671
progress: 37.0 s, 39.0 tps, lat 8488.141 ms stddev 15129.849
progress: 38.0 s, 47.0 tps, lat 12140.015 ms stddev 16098.595
progress: 39.0 s, 63.9 tps, lat 9525.523 ms stddev 15603.099
progress: 40.0 s, 64.0 tps, lat 11248.021 ms stddev 16118.116
progress: 41.0 s, 30.0 tps, lat 12375.117 ms stddev 17397.134
progress: 42.0 s, 30.0 tps, lat 11092.475 ms stddev 17997.073
progress: 43.0 s, 51.0 tps, lat 11488.794 ms stddev 18135.660
progress: 44.0 s, 35.0 tps, lat 11243.333 ms stddev 18802.389
progress: 45.0 s, 56.1 tps, lat 9892.959 ms stddev 18010.395
progress: 46.0 s, 29.0 tps, lat 17224.308 ms stddev 20820.138
progress: 47.0 s, 52.0 tps, lat 13475.267 ms stddev 20866.198
progress: 48.0 s, 52.0 tps, lat 8386.839 ms stddev 17733.223
progress: 49.0 s, 65.0 tps, lat 9060.374 ms stddev 18574.099
progress: 50.0 s, 29.0 tps, lat 10390.055 ms stddev 19808.192
progress: 51.0 s, 54.1 tps, lat 15433.057 ms stddev 21218.736
progress: 52.0 s, 39.0 tps, lat 18607.422 ms stddev 23413.561
progress: 53.0 s, 62.0 tps, lat 9898.151 ms stddev 18971.511
progress: 54.0 s, 34.0 tps, lat 9172.970 ms stddev 18655.790
progress: 55.0 s, 35.0 tps, lat 16339.829 ms stddev 24009.687
progress: 56.0 s, 49.0 tps, lat 11474.089 ms stddev 22152.509
progress: 57.0 s, 15.0 tps, lat 23273.790 ms stddev 23972.075
progress: 58.0 s, 45.0 tps, lat 17884.887 ms stddev 24246.962
progress: 59.0 s, 9.0 tps, lat 26061.653 ms stddev 28924.382
progress: 60.0 s, 34.0 tps, lat 17555.891 ms stddev 26873.251
progress: 61.0 s, 15.0 tps, lat 16637.255 ms stddev 22135.661
progress: 62.0 s, 20.0 tps, lat 21534.107 ms stddev 29106.973
progress: 63.0 s, 32.0 tps, lat 9828.245 ms stddev 22411.644
progress: 64.0 s, 61.1 tps, lat 17278.688 ms stddev 26523.489
progress: 65.0 s, 22.0 tps, lat 17707.084 ms stddev 28519.434
progress: 66.0 s, 29.0 tps, lat 14907.572 ms stddev 25857.086
progress: 67.0 s, 20.0 tps, lat 19984.031 ms stddev 30240.857
progress: 68.0 s, 37.0 tps, lat 13499.886 ms stddev 26002.883
progress: 69.0 s, 20.0 tps, lat 24032.741 ms stddev 32445.249
progress: 70.0 s, 38.0 tps, lat 23151.399 ms stddev 31408.612
progress: 71.0 s, 25.0 tps, lat 23165.598 ms stddev 32441.789
progress: 72.0 s, 40.0 tps, lat 10862.140 ms stddev 25275.667
progress: 73.0 s, 30.0 tps, lat 14560.809 ms stddev 28686.763
progress: 74.0 s, 14.0 tps, lat 26269.971 ms stddev 34970.753
progress: 75.0 s, 41.0 tps, lat 17504.487 ms stddev 30219.588
progress: 76.0 s, 49.0 tps, lat 15546.103 ms stddev 30200.665
progress: 77.0 s, 26.0 tps, lat 14385.324 ms stddev 26674.468
progress: 78.0 s, 42.0 tps, lat 22232.188 ms stddev 34742.547
progress: 79.0 s, 15.0 tps, lat 22361.853 ms stddev 33895.018
progress: 80.0 s, 45.0 tps, lat 17768.734 ms stddev 32813.238
progress: 81.0 s, 36.0 tps, lat 15820.789 ms stddev 31662.068
progress: 82.0 s, 31.0 tps, lat 16553.029 ms stddev 31800.897
progress: 83.0 s, 39.0 tps, lat 10799.064 ms stddev 27374.919
progress: 84.0 s, 28.0 tps, lat 27518.499 ms stddev 38362.262
progress: 85.0 s, 27.0 tps, lat 15802.221 ms stddev 32525.404
progress: 86.0 s, 40.0 tps, lat 20152.181 ms stddev 35171.042
progress: 87.0 s, 32.0 tps, lat 20598.004 ms stddev 34830.062
progress: 88.0 s, 30.0 tps, lat 14803.086 ms stddev 32350.232
progress: 89.0 s, 28.0 tps, lat 19647.986 ms stddev 35859.938
progress: 90.0 s, 40.0 tps, lat 18435.264 ms stddev 35364.559
progress: 91.0 s, 6.0 tps, lat 45248.291 ms stddev 45044.607
progress: 92.0 s, 32.0 tps, lat 29046.606 ms stddev 41959.102
progress: 93.0 s, 18.0 tps, lat 20746.328 ms stddev 38230.543
progress: 94.0 s, 49.0 tps, lat 21428.576 ms stddev 38599.069
progress: 95.0 s, 27.0 tps, lat 14428.229 ms stddev 33301.365
progress: 96.0 s, 38.0 tps, lat 18041.058 ms stddev 36628.789
progress: 97.0 s, 50.0 tps, lat 17589.414 ms stddev 36748.200
progress: 98.0 s, 47.0 tps, lat 16817.047 ms stddev 36381.922
progress: 99.0 s, 31.0 tps, lat 16137.795 ms stddev 35997.819
progress: 100.0 s, 32.0 tps, lat 21987.270 ms stddev 40859.388
progress: 101.0 s, 12.0 tps, lat 66793.331 ms stddev 47041.846
progress: 102.0 s, 161.0 tps, lat 84082.482 ms stddev 22621.806
progress: 103.0 s, 50.0 tps, lat 38104.113 ms stddev 21406.175
progress: 104.0 s, 40.0 tps, lat 37981.012 ms stddev 27412.163
progress: 105.0 s, 32.0 tps, lat 32448.045 ms stddev 27158.082
progress: 106.0 s, 39.0 tps, lat 25246.829 ms stddev 23138.786
progress: 107.0 s, 29.0 tps, lat 22691.016 ms stddev 23348.412
progress: 108.0 s, 32.0 tps, lat 20934.772 ms stddev 27771.861
progress: 109.0 s, 26.0 tps, lat 21292.394 ms stddev 31416.424
progress: 110.0 s, 24.0 tps, lat 99099.590 ms stddev 27154.536
transaction type: test.sql
scaling factor: 1
query mode: simple
number of clients: 1000
number of threads: 36
duration: 100 s
number of transactions actually processed: 4518
latency average = 23748.869 ms
latency stddev = 34606.615 ms
tps = 40.811158 (including connections establishing)
tps = 40.815387 (excluding connections establishing)

2. Yury's shared locks patch

[kk(at)hp06 knizhnik]$ pgbench -n -c 1000 -j 36 -T 100 -P 1 -f test.sql
postgres
progress: 1.0 s, 161.9 tps, lat 58.956 ms stddev 65.879
progress: 2.0 s, 75.0 tps, lat 432.110 ms stddev 655.010
progress: 3.0 s, 111.0 tps, lat 312.127 ms stddev 669.351
progress: 4.0 s, 62.0 tps, lat 716.576 ms stddev 1262.699
progress: 5.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 6.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 7.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 8.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 9.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 10.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 11.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 12.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 13.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 14.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 15.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 16.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 17.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 18.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 19.0 s, 0.0 tps, lat 0.000 ms stddev 0.000
progress: 20.0 s, 33.0 tps, lat 5910.665 ms stddev 8733.552
progress: 21.0 s, 20.0 tps, lat 4190.000 ms stddev 8012.222
progress: 22.0 s, 44.0 tps, lat 4452.898 ms stddev 8469.555
progress: 23.0 s, 17.0 tps, lat 7951.775 ms stddev 10550.763
progress: 24.0 s, 39.0 tps, lat 4894.502 ms stddev 9270.031
progress: 25.0 s, 48.0 tps, lat 4658.159 ms stddev 9365.012
progress: 26.0 s, 19.0 tps, lat 6740.618 ms stddev 11017.741
progress: 27.0 s, 34.0 tps, lat 6265.141 ms stddev 11004.369
progress: 28.0 s, 33.0 tps, lat 10034.798 ms stddev 13039.985
progress: 29.0 s, 24.0 tps, lat 13023.072 ms stddev 13941.556
progress: 30.0 s, 47.0 tps, lat 6365.943 ms stddev 11922.151
progress: 31.0 s, 31.0 tps, lat 5964.649 ms stddev 11769.435
progress: 32.0 s, 18.0 tps, lat 12246.518 ms stddev 15149.607
progress: 33.0 s, 32.0 tps, lat 5164.978 ms stddev 11534.913
progress: 34.0 s, 11.0 tps, lat 18304.152 ms stddev 16536.782
progress: 35.0 s, 44.0 tps, lat 9330.479 ms stddev 14948.877
progress: 36.0 s, 24.0 tps, lat 11817.116 ms stddev 16467.731
progress: 37.0 s, 41.0 tps, lat 16237.412 ms stddev 17303.912
progress: 38.0 s, 19.0 tps, lat 13821.626 ms stddev 17843.619
progress: 39.0 s, 46.0 tps, lat 6945.577 ms stddev 13146.942
progress: 40.0 s, 46.0 tps, lat 6160.800 ms stddev 13194.172
progress: 41.0 s, 8.0 tps, lat 15238.093 ms stddev 19417.694
progress: 42.0 s, 39.0 tps, lat 9974.308 ms stddev 17210.077
progress: 43.0 s, 15.0 tps, lat 14262.093 ms stddev 19735.918
progress: 44.0 s, 32.0 tps, lat 14679.202 ms stddev 18600.461
progress: 45.0 s, 17.0 tps, lat 2808.233 ms stddev 10258.923
progress: 46.0 s, 8.0 tps, lat 22812.538 ms stddev 22501.104
progress: 47.0 s, 27.0 tps, lat 10755.093 ms stddev 17452.703
progress: 48.0 s, 28.0 tps, lat 12695.089 ms stddev 20150.626
progress: 49.0 s, 40.0 tps, lat 7417.723 ms stddev 17090.798
progress: 50.0 s, 26.0 tps, lat 8836.551 ms stddev 17367.063
progress: 51.0 s, 36.0 tps, lat 10102.477 ms stddev 18143.073
progress: 52.0 s, 18.0 tps, lat 21193.476 ms stddev 24130.141
progress: 53.0 s, 31.0 tps, lat 5231.374 ms stddev 15250.089
progress: 54.0 s, 16.0 tps, lat 17832.545 ms stddev 23926.820
progress: 55.0 s, 40.0 tps, lat 8267.716 ms stddev 19144.680
progress: 56.0 s, 24.0 tps, lat 9717.556 ms stddev 20320.800
progress: 57.0 s, 112.1 tps, lat 29832.052 ms stddev 28082.255
progress: 58.0 s, 80.9 tps, lat 14180.656 ms stddev 24662.298
progress: 59.0 s, 65.1 tps, lat 11692.933 ms stddev 23265.631
progress: 60.0 s, 71.0 tps, lat 14238.960 ms stddev 25257.791
progress: 61.0 s, 73.9 tps, lat 13853.016 ms stddev 25232.753
progress: 62.0 s, 85.0 tps, lat 12292.783 ms stddev 24429.711
progress: 63.0 s, 47.0 tps, lat 14646.395 ms stddev 26355.656
progress: 64.0 s, 60.1 tps, lat 13740.789 ms stddev 25977.830
progress: 65.0 s, 69.0 tps, lat 14942.281 ms stddev 27052.182
progress: 66.0 s, 58.0 tps, lat 14530.473 ms stddev 26876.548
progress: 67.0 s, 56.0 tps, lat 12788.740 ms stddev 25702.123
progress: 68.0 s, 61.0 tps, lat 18125.661 ms stddev 29011.571
progress: 69.0 s, 50.0 tps, lat 7588.453 ms stddev 18761.996
progress: 70.0 s, 50.0 tps, lat 12869.978 ms stddev 21733.866
progress: 71.0 s, 51.0 tps, lat 7888.145 ms stddev 18308.426
progress: 72.0 s, 24.0 tps, lat 20570.400 ms stddev 24677.345
progress: 73.0 s, 35.0 tps, lat 12614.746 ms stddev 21674.382
progress: 74.0 s, 39.0 tps, lat 8972.717 ms stddev 19373.101
progress: 75.0 s, 24.0 tps, lat 17855.659 ms stddev 26005.986
progress: 76.0 s, 48.0 tps, lat 17213.313 ms stddev 25059.842
progress: 77.0 s, 46.0 tps, lat 10431.720 ms stddev 21575.560
progress: 78.0 s, 44.0 tps, lat 18981.286 ms stddev 27742.090
progress: 79.0 s, 17.0 tps, lat 26332.168 ms stddev 33125.673
progress: 80.0 s, 33.0 tps, lat 13477.140 ms stddev 20257.123
progress: 81.0 s, 46.0 tps, lat 10610.854 ms stddev 18704.784
progress: 82.0 s, 52.0 tps, lat 10895.657 ms stddev 21817.542
progress: 83.0 s, 48.0 tps, lat 9902.718 ms stddev 19765.415
progress: 84.0 s, 35.0 tps, lat 11279.406 ms stddev 21385.872
progress: 85.0 s, 51.0 tps, lat 17545.936 ms stddev 29036.491
progress: 86.0 s, 39.0 tps, lat 26478.287 ms stddev 27160.865
progress: 87.0 s, 59.0 tps, lat 17854.885 ms stddev 23408.893
progress: 88.0 s, 50.0 tps, lat 9628.923 ms stddev 18956.878
progress: 89.0 s, 64.0 tps, lat 9504.706 ms stddev 17715.302
progress: 90.0 s, 58.0 tps, lat 13678.080 ms stddev 21006.403
progress: 91.0 s, 43.0 tps, lat 9901.618 ms stddev 17408.284
progress: 92.0 s, 32.0 tps, lat 13467.742 ms stddev 22203.125
progress: 93.0 s, 55.0 tps, lat 8606.426 ms stddev 16911.836
progress: 94.0 s, 32.0 tps, lat 8291.617 ms stddev 23614.208
progress: 95.0 s, 38.0 tps, lat 14395.072 ms stddev 27052.394
progress: 96.0 s, 25.0 tps, lat 33590.759 ms stddev 43220.795
progress: 97.0 s, 50.0 tps, lat 15520.320 ms stddev 35150.669
progress: 98.0 s, 16.0 tps, lat 35268.519 ms stddev 42629.424
progress: 99.0 s, 46.0 tps, lat 17419.726 ms stddev 34680.490
progress: 100.0 s, 32.0 tps, lat 30165.553 ms stddev 41068.048
progress: 101.0 s, 20.0 tps, lat 34004.361 ms stddev 44439.703
progress: 102.0 s, 9.0 tps, lat 94924.234 ms stddev 17750.440
progress: 103.0 s, 18.0 tps, lat 78665.820 ms stddev 34437.075
progress: 104.0 s, 7.0 tps, lat 95136.317 ms stddev 19960.028
progress: 105.0 s, 21.0 tps, lat 76378.853 ms stddev 39943.159
progress: 106.0 s, 10.0 tps, lat 99620.400 ms stddev 16800.308
progress: 107.0 s, 175.2 tps, lat 73492.433 ms stddev 39690.326
progress: 108.0 s, 75.0 tps, lat 25470.068 ms stddev 13140.013
progress: 109.0 s, 58.0 tps, lat 24925.175 ms stddev 21826.550
progress: 110.0 s, 41.0 tps, lat 26060.593 ms stddev 32335.285
progress: 111.0 s, 43.0 tps, lat 106188.963 ms stddev 14389.898
progress: 112.0 s, 35.0 tps, lat 104723.980 ms stddev 17978.512
progress: 113.0 s, 133.1 tps, lat 90808.576 ms stddev 32832.832
transaction type: test.sql
scaling factor: 1
query mode: simple
number of clients: 1000
number of threads: 36
duration: 100 s
number of transactions actually processed: 4656
latency average = 23572.699 ms
latency stddev = 35309.693 ms
tps = 41.151969 (including connections establishing)
tps = 41.156079 (excluding connections establishing)

3. My patch:

[kk(at)hp06 knizhnik]$ pgbench -n -c 1000 -j 36 -T 100 -P 1 -f test.sql
postgres
progress: 1.0 s, 109.0 tps, lat 186.699 ms stddev 155.513
progress: 2.0 s, 185.0 tps, lat 858.366 ms stddev 435.616
progress: 3.0 s, 155.0 tps, lat 1454.427 ms stddev 955.026
progress: 4.0 s, 323.2 tps, lat 1844.037 ms stddev 1573.388
progress: 5.0 s, 182.0 tps, lat 2038.689 ms stddev 1959.624
progress: 6.0 s, 139.0 tps, lat 2063.075 ms stddev 2421.067
progress: 7.0 s, 198.0 tps, lat 4243.453 ms stddev 2724.742
progress: 8.0 s, 234.0 tps, lat 5122.093 ms stddev 2582.399
progress: 9.0 s, 175.0 tps, lat 3268.453 ms stddev 3077.928
progress: 10.0 s, 145.0 tps, lat 4339.716 ms stddev 3855.064
progress: 11.0 s, 418.0 tps, lat 3638.447 ms stddev 3717.018
progress: 12.0 s, 254.0 tps, lat 5739.302 ms stddev 4222.194
progress: 13.0 s, 264.0 tps, lat 3463.426 ms stddev 3312.223
progress: 14.0 s, 241.0 tps, lat 3737.628 ms stddev 4345.002
progress: 15.0 s, 231.0 tps, lat 3655.541 ms stddev 3885.624
progress: 16.0 s, 372.0 tps, lat 4965.353 ms stddev 4092.753
progress: 17.0 s, 203.0 tps, lat 4152.482 ms stddev 3115.167
progress: 18.0 s, 189.0 tps, lat 4069.375 ms stddev 4096.535
progress: 19.0 s, 267.0 tps, lat 4495.891 ms stddev 3897.380
progress: 20.0 s, 182.8 tps, lat 2946.705 ms stddev 3371.206
progress: 21.0 s, 144.1 tps, lat 4176.410 ms stddev 2994.048
progress: 22.0 s, 186.0 tps, lat 4095.609 ms stddev 3998.535
progress: 23.0 s, 283.0 tps, lat 4091.103 ms stddev 4337.856
progress: 24.0 s, 413.0 tps, lat 4913.568 ms stddev 3602.845
progress: 25.0 s, 153.0 tps, lat 4897.216 ms stddev 3412.526
progress: 26.0 s, 362.0 tps, lat 4322.345 ms stddev 4745.684
progress: 27.0 s, 229.0 tps, lat 2722.046 ms stddev 2778.627
progress: 28.0 s, 375.0 tps, lat 3074.234 ms stddev 3372.233
progress: 29.0 s, 227.9 tps, lat 4165.033 ms stddev 3554.064
progress: 30.0 s, 403.2 tps, lat 3777.061 ms stddev 3338.528
progress: 31.0 s, 312.0 tps, lat 2692.811 ms stddev 2786.706
progress: 32.0 s, 172.0 tps, lat 2666.640 ms stddev 2557.934
progress: 33.0 s, 327.0 tps, lat 3753.528 ms stddev 3003.476
progress: 34.0 s, 288.0 tps, lat 3700.307 ms stddev 4360.617
progress: 35.0 s, 138.9 tps, lat 2793.501 ms stddev 2973.115
progress: 36.0 s, 199.1 tps, lat 3914.999 ms stddev 3620.217
progress: 37.0 s, 332.0 tps, lat 4438.935 ms stddev 3367.059
progress: 38.0 s, 273.0 tps, lat 3976.717 ms stddev 3605.981
progress: 39.0 s, 350.0 tps, lat 2564.301 ms stddev 3098.142
progress: 40.0 s, 198.0 tps, lat 3821.723 ms stddev 3720.681
progress: 41.0 s, 379.0 tps, lat 3540.596 ms stddev 3716.245
progress: 42.0 s, 337.0 tps, lat 3359.137 ms stddev 3432.100
progress: 43.0 s, 273.0 tps, lat 4083.521 ms stddev 3446.354
progress: 44.0 s, 267.0 tps, lat 3604.277 ms stddev 3931.611
progress: 45.0 s, 221.0 tps, lat 3187.834 ms stddev 3472.713
progress: 46.0 s, 257.0 tps, lat 4420.584 ms stddev 3269.787
progress: 47.0 s, 216.0 tps, lat 4784.282 ms stddev 4078.919
progress: 48.0 s, 340.0 tps, lat 2878.317 ms stddev 3159.234
progress: 49.0 s, 393.0 tps, lat 3296.432 ms stddev 3120.998
progress: 50.0 s, 384.0 tps, lat 3333.966 ms stddev 3632.887
progress: 51.0 s, 179.9 tps, lat 3357.831 ms stddev 3577.181
progress: 52.0 s, 193.1 tps, lat 2740.384 ms stddev 2853.463
progress: 53.0 s, 266.0 tps, lat 3338.786 ms stddev 3294.210
progress: 54.0 s, 198.0 tps, lat 4350.746 ms stddev 3632.925
progress: 55.0 s, 443.0 tps, lat 4533.887 ms stddev 3284.145
progress: 56.0 s, 209.0 tps, lat 2471.820 ms stddev 2872.507
progress: 57.0 s, 243.0 tps, lat 3657.152 ms stddev 3082.953
progress: 58.0 s, 204.0 tps, lat 3758.366 ms stddev 3981.754
progress: 59.0 s, 255.0 tps, lat 3641.082 ms stddev 4062.395
progress: 60.0 s, 331.0 tps, lat 3752.880 ms stddev 3732.255
progress: 61.0 s, 225.0 tps, lat 3390.763 ms stddev 2763.489
progress: 62.0 s, 298.0 tps, lat 4201.300 ms stddev 3632.733
progress: 63.0 s, 106.0 tps, lat 2692.495 ms stddev 3976.275
progress: 64.0 s, 118.0 tps, lat 3870.886 ms stddev 4552.055
progress: 65.0 s, 111.0 tps, lat 1877.879 ms stddev 2530.083
progress: 66.0 s, 114.0 tps, lat 4240.246 ms stddev 4699.575
progress: 67.0 s, 214.0 tps, lat 4742.589 ms stddev 4249.912
progress: 68.0 s, 279.0 tps, lat 5303.721 ms stddev 5630.854
progress: 69.0 s, 181.0 tps, lat 5367.429 ms stddev 5191.225
progress: 70.0 s, 223.0 tps, lat 5220.545 ms stddev 4810.474
progress: 71.0 s, 181.0 tps, lat 5094.250 ms stddev 4598.197
progress: 72.0 s, 191.0 tps, lat 4775.279 ms stddev 4638.785
progress: 73.0 s, 121.0 tps, lat 6151.599 ms stddev 6044.989
progress: 74.0 s, 352.0 tps, lat 5722.979 ms stddev 5637.691
progress: 75.0 s, 313.0 tps, lat 3681.700 ms stddev 4511.268
progress: 76.0 s, 293.9 tps, lat 6134.980 ms stddev 5633.180
progress: 77.0 s, 292.1 tps, lat 4964.182 ms stddev 5115.833
progress: 78.0 s, 247.0 tps, lat 2958.631 ms stddev 3396.316
progress: 79.0 s, 308.0 tps, lat 4295.905 ms stddev 5392.345
progress: 80.0 s, 260.0 tps, lat 5192.128 ms stddev 4042.820
progress: 81.0 s, 244.0 tps, lat 2378.675 ms stddev 2619.194
progress: 82.0 s, 261.0 tps, lat 3619.289 ms stddev 3678.498
progress: 83.0 s, 193.0 tps, lat 4519.653 ms stddev 4820.241
progress: 84.0 s, 313.0 tps, lat 3838.839 ms stddev 4010.695
progress: 85.0 s, 265.0 tps, lat 3470.704 ms stddev 3009.119
progress: 86.0 s, 169.0 tps, lat 3113.572 ms stddev 3338.449
progress: 87.0 s, 181.0 tps, lat 2722.756 ms stddev 3552.120
progress: 88.0 s, 192.0 tps, lat 4767.495 ms stddev 4794.403
progress: 89.0 s, 276.0 tps, lat 4417.211 ms stddev 4012.534
progress: 90.0 s, 249.0 tps, lat 4600.363 ms stddev 4613.885
progress: 91.0 s, 136.0 tps, lat 5292.106 ms stddev 3254.580
progress: 92.0 s, 335.0 tps, lat 3606.878 ms stddev 4238.592
progress: 93.0 s, 183.0 tps, lat 4802.608 ms stddev 4424.506
progress: 94.0 s, 208.0 tps, lat 4257.261 ms stddev 3882.918
progress: 95.0 s, 154.0 tps, lat 5939.258 ms stddev 4506.066
progress: 96.0 s, 245.0 tps, lat 4968.774 ms stddev 3695.050
progress: 97.0 s, 133.9 tps, lat 3991.399 ms stddev 4884.086
progress: 98.0 s, 309.1 tps, lat 4340.668 ms stddev 4231.593
progress: 99.0 s, 88.0 tps, lat 5672.978 ms stddev 4776.332
progress: 100.0 s, 221.0 tps, lat 3617.880 ms stddev 4441.404
progress: 101.0 s, 486.0 tps, lat 7574.035 ms stddev 4135.087
transaction type: test.sql
scaling factor: 1
query mode: simple
number of clients: 1000
number of threads: 36
duration: 100 s
number of transactions actually processed: 25206
latency average = 3990.599 ms
latency stddev = 3982.713 ms
tps = 248.988411 (including connections establishing)
tps = 249.015469 (excluding connections establishing)

As you can see performance and latency are ~6 times worser.  Please also
notice periods of zero TPS in first two cases.

--
Konstantin Knizhnik
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company