Re: Postgres stucks in deadlock detection

пт, 13 апр. 2018 г., 21:10 Andres Freund <andres@anarazel.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@postgrespro.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@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@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@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