Re: That EXPLAIN ANALYZE patch still needs work - Mailing list pgsql-hackers

Ah-hah, I've sussed it.  The faulty assumption can actually be stated
as: "all the executions, except maybe the first, will take approximately
the same amount of time".  The failing test case I've been looking at
is one where the system decides to use a "batched" hash join, and in
this plan type some iterations take much longer than others.  (The
apparent dependence on targetlist width is now easy to understand,
because that affects the estimated hashtable size and hence the decision
whether batching is needed.  I'm not sure why I don't see the effect
when running the identical case on my other machine, but since the
other one is a 64-bit machine its space calculations are probably a
bit different.)

I added some printf's to instrument.c to print out the actual time
measurements for each sample, as well as the calculations in
InstrEndLoop.  Attached are the printouts that occurred for the HashJoin
node.  The thing that is killing the extrapolation is of course the very
large time for iteration 2, which the extrapolation includes in its
average.  But there's well over 10:1 variation in the later samples
as well.

On reflection it's easy to imagine other cases where some iterations
take much longer than others in a not-very-predictable way.  For
instance, a join where only a subset of the outer tuples have a match
is going to act that way.  I don't think there's any good way that we
can be sure we have a representative sample of executions, and so I'm
afraid this approach to sampling EXPLAIN ANALYZE is a failure.

I propose we revert this patch and think about an interrupt-driven
sampling method instead.
        regards, tom lane


401489a0 1: 331616 usec in iter 1
401489a0 1: 110338 usec in iter 2
401489a0 1: 54 usec in iter 3
401489a0 1: 99 usec in iter 4
401489a0 1: 77 usec in iter 5
401489a0 1: 145 usec in iter 6
401489a0 1: 117 usec in iter 7
401489a0 1: 33 usec in iter 8
401489a0 1: 97 usec in iter 9
401489a0 1: 98 usec in iter 10
401489a0 1: 52 usec in iter 11
401489a0 1: 33 usec in iter 12
401489a0 1: 51 usec in iter 13
401489a0 1: 83 usec in iter 14
401489a0 1: 153 usec in iter 15
401489a0 1: 115 usec in iter 16
401489a0 1: 52 usec in iter 17
401489a0 1: 242 usec in iter 18
401489a0 1: 48 usec in iter 19
401489a0 1: 87 usec in iter 20
401489a0 1: 23 usec in iter 21
401489a0 1: 80 usec in iter 22
401489a0 1: 57 usec in iter 23
401489a0 1: 17 usec in iter 24
401489a0 1: 51 usec in iter 25
401489a0 1: 18 usec in iter 26
401489a0 1: 16 usec in iter 27
401489a0 1: 100 usec in iter 28
401489a0 1: 45 usec in iter 29
401489a0 1: 174 usec in iter 30
401489a0 1: 131 usec in iter 31
401489a0 1: 17 usec in iter 32
401489a0 1: 45 usec in iter 33
401489a0 1: 16 usec in iter 34
401489a0 1: 120 usec in iter 35
401489a0 1: 15 usec in iter 36
401489a0 1: 17 usec in iter 37
401489a0 1: 15 usec in iter 38
401489a0 1: 48 usec in iter 39
401489a0 1: 127 usec in iter 40
401489a0 1: 36 usec in iter 41
401489a0 1: 41 usec in iter 42
401489a0 1: 69 usec in iter 43
401489a0 1: 50 usec in iter 44
401489a0 1: 104 usec in iter 45
401489a0 1: 22 usec in iter 46
401489a0 1: 50 usec in iter 47
401489a0 1: 17 usec in iter 48
401489a0 1: 47 usec in iter 49
401489a0 1: 54 usec in iter 50
401489a0 1: 46 usec in iter 51
401489a0 1: 20 usec in iter 54
401489a0 1: 38 usec in iter 55
401489a0 1: 68 usec in iter 56
401489a0 1: 17 usec in iter 60
401489a0 1: 16 usec in iter 61
401489a0 1: 15 usec in iter 67
401489a0 1: 31 usec in iter 68
401489a0 1: 15 usec in iter 70
401489a0 1: 61 usec in iter 78
401489a0 1: 143 usec in iter 85
401489a0 1: 21 usec in iter 89
401489a0 1: 14 usec in iter 96
401489a0 1: 21 usec in iter 104
401489a0 1: 21 usec in iter 107
401489a0 1: 16 usec in iter 116
401489a0 1: 194 usec in iter 118
401489a0 1: 136 usec in iter 122
401489a0 1: 34 usec in iter 127
401489a0 1: 46 usec in iter 131
401489a0 1: 15 usec in iter 133
401489a0 1: 15 usec in iter 135
401489a0 1: 34 usec in iter 137
401489a0 1: 54 usec in iter 142
401489a0 1: 206 usec in iter 151
401489a0 1: 75 usec in iter 162
401489a0 1: 20 usec in iter 172
401489a0 1: 66 usec in iter 177
401489a0 1: 21 usec in iter 181
401489a0 1: 69 usec in iter 186
401489a0 1: 16 usec in iter 193
401489a0 1: 46 usec in iter 201
401489a0 1: 33 usec in iter 210
401489a0 1: 50 usec in iter 216
401489a0 1: 21 usec in iter 222
401489a0 1: 18 usec in iter 224
401489a0 1: 33 usec in iter 229
401489a0 1: 20 usec in iter 232
401489a0 1: 44 usec in iter 236
401489a0 1: 29 usec in iter 239
401489a0 1: 34 usec in iter 240
401489a0 1: 31 usec in iter 241
401489a0 1: 27 usec in iter 254
401489a0 1: 45 usec in iter 257
401489a0 1: 147 usec in iter 259
401489a0 1: 15 usec in iter 269
401489a0 1: 16 usec in iter 278
401489a0 1: 14 usec in iter 279
401489a0 1: 58 usec in iter 290
401489a0 1: 15 usec in iter 291
401489a0 1: 53 usec in iter 295
401489a0 1: 15 usec in iter 306
401489a0 1: 16 usec in iter 318
401489a0 1: 34 usec in iter 328
401489a0 1: 37 usec in iter 339
401489a0 1: 28 usec in iter 346
401489a0 1: 21 usec in iter 353
401489a0 1: 15 usec in iter 361
401489a0 1: 49 usec in iter 370
401489a0 1: 61 usec in iter 380
401489a0 1: 21 usec in iter 385
401489a0 1: 50 usec in iter 397
401489a0 1: 36 usec in iter 411
401489a0 1: 44 usec in iter 417
401489a0 1: 55 usec in iter 420
401489a0 1: 15 usec in iter 427
401489a0 1: 74 usec in iter 429
401489a0 1: 178 usec in iter 433
401489a0 1: 182 usec in iter 440
401489a0 1: 41 usec in iter 454
401489a0 1: 39 usec in iter 455
401489a0 1: 28 usec in iter 470
401489a0 1: 57 usec in iter 473
401489a0 1: 15 usec in iter 480
401489a0 1: 21 usec in iter 489
401489a0 1: 76 usec in iter 498
401489a0 1: 38 usec in iter 513
401489a0 1: 21 usec in iter 523
401489a0 1: 33 usec in iter 529
401489a0 1: 39 usec in iter 545
401489a0 1: 25 usec in iter 559
401489a0 1: 27 usec in iter 566
401489a0 1: 15 usec in iter 574
401489a0 1: 25 usec in iter 590
401489a0 1: 62 usec in iter 606
401489a0 1: 27 usec in iter 610
401489a0 1: 16 usec in iter 625
401489a0 1: 49 usec in iter 641
401489a0 1: 27 usec in iter 654
401489a0 1: 22 usec in iter 665
401489a0 1: 17 usec in iter 669
401489a0 1: 39 usec in iter 682
401489a0 1: 27 usec in iter 684
401489a0 1: 68 usec in iter 697
401489a0 1: 15 usec in iter 700
401489a0 1: 16 usec in iter 712
401489a0 1: 15 usec in iter 728
401489a0 1: 22 usec in iter 746
401489a0 1: 16 usec in iter 752
401489a0 1: 45 usec in iter 766
401489a0 1: 44 usec in iter 777
401489a0 1: 33 usec in iter 785
401489a0 1: 21 usec in iter 802
401489a0 1: 23 usec in iter 814
401489a0 1: 15 usec in iter 820
401489a0 1: 21 usec in iter 839
401489a0 1: 23 usec in iter 840
401489a0 1: 39 usec in iter 858
401489a0 1: 94 usec in iter 867
401489a0 1: 33 usec in iter 877
401489a0 1: 56 usec in iter 895
401489a0 1: 14 usec in iter 898
401489a0 1: 22 usec in iter 900
401489a0 1: 14 usec in iter 910
401489a0 1: 20 usec in iter 918
401489a0 1: 14 usec in iter 937
401489a0 1: 28 usec in iter 942
401489a0 1: 29 usec in iter 944
401489a0 1: 21 usec in iter 947
401489a0 1: 68 usec in iter 957
401489a0 1: 46 usec in iter 969
401489a0 1: 15 usec in iter 971
401489a0 1: 16 usec in iter 987
401489a0 1: 22 usec in iter 1000
401489a0 1: 36 usec in iter 1001
401489a0 1: 22 usec in iter 1017
401489a0 1: 17 usec in iter 1031
401489a0 1: 36 usec in iter 1042
401489a0 1: 21 usec in iter 1062
401489a0 1: 15 usec in iter 1077
401489a0 1: 21 usec in iter 1097
401489a0 1: 88 usec in iter 1114
401489a0 1: 62 usec in iter 1123
401489a0 1: 16 usec in iter 1131
401489a0 1: 21 usec in iter 1149
401489a0 1: 15 usec in iter 1156
401489a0 1: 33 usec in iter 1177
401489a0 1: 22 usec in iter 1190
401489a0 1: 83 usec in iter 1201
401489a0 1: 16 usec in iter 1209
401489a0 1: 184 usec in iter 1224
401489a0 1: 33 usec in iter 1234
401489a0 1: 39 usec in iter 1236
401489a0 1: 21 usec in iter 1247
401489a0 1: 33 usec in iter 1267
401489a0 1: 16 usec in iter 1277
401489a0 1: 15 usec in iter 1297
401489a0 1: 14 usec in iter 1319
401489a0 1: 21 usec in iter 1329
401489a0 1: 15 usec in iter 1342
401489a0 1: 16 usec in iter 1357
401489a0 1: 57 usec in iter 1378
401489a0 1: 16 usec in iter 1400
401489a0 1: 16 usec in iter 1410
401489a0 1: 113 usec in iter 1417
401489a0 1: 16 usec in iter 1418
401489a0 1: 15 usec in iter 1433
401489a0 1: 23 usec in iter 1434
401489a0 1: 96 usec in iter 1442
401489a0 1: 30 usec in iter 1449
401489a0 1: 121 usec in iter 1454
401489a0 1: 16 usec in iter 1462
401489a0 1: 29 usec in iter 1482
401489a0 1: 48 usec in iter 1490
401489a0 1: 40 usec in iter 1512
401489a0 1: 20 usec in iter 1529
401489a0 1: 48 usec in iter 1545
401489a0 1: 45 usec in iter 1547
401489a0 1: 271 usec in iter 1557
401489a0 1: 15 usec in iter 1558
401489a0 1: 44 usec in iter 1576
401489a0 1: 15 usec in iter 1592
401489a0 1: 148 usec in iter 1616
401489a0 1: 15 usec in iter 1640
401489a0 1: 34 usec in iter 1650
401489a0 1: 27 usec in iter 1659
401489a0 1: 15 usec in iter 1673
401489a0 1: 59 usec in iter 1686
401489a0 1: 22 usec in iter 1689
401489a0 1: 16 usec in iter 1696
401489a0 1: 27 usec in iter 1715
401489a0 1: 23 usec in iter 1736
401489a0 1: 16 usec in iter 1749
401489a0 1: 27 usec in iter 1757
401489a0 1: 15 usec in iter 1777
401489a0 1: 15 usec in iter 1801
401489a0 1: 16 usec in iter 1804
401489a0 1: 227 usec in iter 1829
401489a0 1: 27 usec in iter 1848
401489a0 1: 16 usec in iter 1869
401489a0 1: 33 usec in iter 1881
401489a0 1: 57 usec in iter 1902
401489a0 1: 29 usec in iter 1926
401489a0 1: 15 usec in iter 1932
401489a0 1: 58 usec in iter 1955
401489a0 1: 15 usec in iter 1980
401489a0 1: 22 usec in iter 1992
401489a0 1: 14 usec in iter 2001
401489a0 1: 56 usec in iter 2010
401489a0 1: 22 usec in iter 2018
401489a0 1: 16 usec in iter 2043
401489a0 1: 15 usec in iter 2046
401489a0 1: 50 usec in iter 2051
401489a0 1: 16 usec in iter 2053
401489a0 1: 22 usec in iter 2078
401489a0 1: 89 usec in iter 2094
401489a0 1: 69 usec in iter 2103
401489a0 1: 33 usec in iter 2121
401489a0 1: 28 usec in iter 2124
401489a0 1: 34 usec in iter 2135
401489a0 1: 22 usec in iter 2148
401489a0 1: 22 usec in iter 2167
401489a0 1: 15 usec in iter 2186
401489a0 1: 40 usec in iter 2199
401489a0 1: 23 usec in iter 2219
401489a0 1: 21 usec in iter 2223
401489a0 1: 27 usec in iter 2235
401489a0 1: 14 usec in iter 2238
401489a0 1: 22 usec in iter 2250
401489a0 1: 31 usec in iter 2252
401489a0 1: 36 usec in iter 2259
401489a0 1: 15 usec in iter 2282
401489a0 1: 259 usec in iter 2300
401489a0 1: 37 usec in iter 2318
401489a0 1: 21 usec in iter 2331
401489a0 1: 16 usec in iter 2345
401489a0 1: 15 usec in iter 2350
401489a0 1: 16 usec in iter 2361
401489a0 1: 69 usec in iter 2364
401489a0 1: 29 usec in iter 2374
401489a0 1: 33 usec in iter 2383
401489a0 1: 116 usec in iter 2400
401489a0 1: 37 usec in iter 2420
401489a0 1: 39 usec in iter 2447
401489a0 1: 29 usec in iter 2455
401489a0 1: 114 usec in iter 2476
401489a0 1: 33 usec in iter 2488
401489a0 1: 22 usec in iter 2493
401489a0 1: 53 usec in iter 2512
401489a0 1: 22 usec in iter 2539
401489a0 1: 57 usec in iter 2563
401489a0 1: 32 usec in iter 2564
401489a0 1: 39 usec in iter 2572
401489a0 1: 22 usec in iter 2574
401489a0 1: 14 usec in iter 2597
401489a0 1: 74 usec in iter 2610
401489a0 1: 23 usec in iter 2618
401489a0 1: 21 usec in iter 2626
401489a0 1: 16 usec in iter 2627
401489a0 1: 45 usec in iter 2653
401489a0 1: 28 usec in iter 2662
401489a0 1: 20 usec in iter 2679
401489a0 1: 27 usec in iter 2694
401489a0 1: 17 usec in iter 2696
401489a0 1: 14 usec in iter 2706
401489a0 1: 22 usec in iter 2720
401489a0 1: 36 usec in iter 2742
401489a0 1: 20 usec in iter 2753
401489a0 1: 20 usec in iter 2761
401489a0 1: 16 usec in iter 2788
401489a0 1: 22 usec in iter 2795
401489a0 1: 16 usec in iter 2804
401489a0 1: 144 usec in iter 2812
401489a0 1: 16 usec in iter 2817
401489a0 1: 16 usec in iter 2834
401489a0 1: 16 usec in iter 2853
401489a0 1: 53 usec in iter 2872
401489a0 1: 22 usec in iter 2882
401489a0 1: 28 usec in iter 2907
401489a0 1: 38 usec in iter 2922
401489a0 1: 56 usec in iter 2935
401489a0 1: 188 usec in iter 2954
401489a0 1: 15 usec in iter 2964
401489a0 1: 22 usec in iter 2984
401489a0 1: 23 usec in iter 3007
401489a0 1: 27 usec in iter 3028
401489a0 1: 16 usec in iter 3051
401489a0 1: 178 usec in iter 3064
401489a0 1: 15 usec in iter 3082
401489a0 1: 20 usec in iter 3083
401489a0 1: 15 usec in iter 3097
401489a0 1: 14 usec in iter 3120
401489a0 1: 16 usec in iter 3126
401489a0 1: 15 usec in iter 3145
401489a0 1: 15 usec in iter 3171
401489a0 1: 15 usec in iter 3200
401489a0 1: 15 usec in iter 3218
401489a0 1: 15 usec in iter 3242
401489a0 1: 50 usec in iter 3263
401489a0 1: 16 usec in iter 3267
401489a0 1: 15 usec in iter 3284
401489a0 1: 14 usec in iter 3300
401489a0 1: 16 usec in iter 3317
401489a0 1: 15 usec in iter 3342
401489a0 1: 14 usec in iter 3372
401489a0 1: 15 usec in iter 3377
401489a0 1: 14 usec in iter 3379
401489a0 1: 14 usec in iter 3389
401489a0 1: 14 usec in iter 3417
401489a0 1: 16 usec in iter 3419
401489a0 1: 16 usec in iter 3446
401489a0 1: 16 usec in iter 3461
401489a0 1: 15 usec in iter 3475
401489a0 1: 16 usec in iter 3484
401489a0 1: 16 usec in iter 3489
401489a0 1: 14 usec in iter 3511
401489a0 1: 15 usec in iter 3519
401489a0 1: 15 usec in iter 3527
401489a0 1: 15 usec in iter 3552
401489a0 1: 15 usec in iter 3572
401489a0 1: 16 usec in iter 3574
401489a0 1: 14 usec in iter 3584
401489a0 1: 15 usec in iter 3586
401489a0 1: 16 usec in iter 3610
401489a0 1: 14 usec in iter 3619
401489a0 1: 15 usec in iter 3629
401489a0 1: 15 usec in iter 3658
401489a0 1: 14 usec in iter 3682
401489a0 1: 14 usec in iter 3683
401489a0 1: 15 usec in iter 3692
401489a0 1: 15 usec in iter 3718
401489a0 1: 15 usec in iter 3749
401489a0 1: 15 usec in iter 3758
401489a0 1: 16 usec in iter 3783
401489a0 1: 15 usec in iter 3796
401489a0 1: 15 usec in iter 3812
401489a0 1: 15 usec in iter 3818
401489a0 1: 15 usec in iter 3826
401489a0 1: 15 usec in iter 3836
401489a0 1: 15 usec in iter 3851
401489a0 1: 15 usec in iter 3875
401489a0 1: 57 usec in iter 3891
401489a0 1: 15 usec in iter 3922
401489a0 1: 15 usec in iter 3925
401489a0 1: 15 usec in iter 3933
401489a0 1: 16 usec in iter 3942
401489a0 1: 15 usec in iter 3967
401489a0 1: 14 usec in iter 3994
401489a0 1: 14 usec in iter 4015
401489a0 1: 15 usec in iter 4025
401489a0 1: 16 usec in iter 4056
401489a0 1: 15 usec in iter 4063
401489a0 1: 15 usec in iter 4070
401489a0 1: 15 usec in iter 4079
401489a0 1: 15 usec in iter 4100
401489a0 1: 15 usec in iter 4122
401489a0 1: 14 usec in iter 4149
401489a0 1: 14 usec in iter 4171
401489a0 1: 14 usec in iter 4186
401489a0 1: 16 usec in iter 4208
401489a0 1: 15 usec in iter 4231
401489a0 1: 15 usec in iter 4262
401489a0 1: 14 usec in iter 4280
401489a0 1: 14 usec in iter 4293
401489a0 1: 15 usec in iter 4300
401489a0 1: 14 usec in iter 4323
401489a0 1: 34 usec in iter 4336
401489a0 1: 15 usec in iter 4359
401489a0 1: 15 usec in iter 4378
401489a0 1: 15 usec in iter 4384
401489a0 1: 15 usec in iter 4388
401489a0 1: 15 usec in iter 4406
401489a0 1: 14 usec in iter 4432
401489a0 1: 15 usec in iter 4452
401489a0 1: 15 usec in iter 4460
401489a0 1: 15 usec in iter 4469
401489a0 1: 54 usec in iter 4492
401489a0 1: 15 usec in iter 4493
401489a0 1: 16 usec in iter 4505
401489a0 1: 16 usec in iter 4527
401489a0 1: 16 usec in iter 4557
401489a0 1: 15 usec in iter 4569
401489a0 1: 16 usec in iter 4588
401489a0 1: 15 usec in iter 4598
401489a0 1: 15 usec in iter 4607
401489a0 1: 55 usec in iter 4629
401489a0 1: 14 usec in iter 4644
401489a0 1: 14 usec in iter 4652
401489a0 1: 14 usec in iter 4680
401489a0 1: 14 usec in iter 4692
401489a0 1: 16 usec in iter 4696
401489a0 1: 15 usec in iter 4706
401489a0 1: 15 usec in iter 4718
401489a0 1: 15 usec in iter 4722
401489a0 1: 14 usec in iter 4730
401489a0 1: 16 usec in iter 4731
401489a0 1: 15 usec in iter 4743
401489a0 1: 15 usec in iter 4754
401489a0 1: 16 usec in iter 4785
401489a0 1: 14 usec in iter 4787
401489a0 1: 14 usec in iter 4808
401489a0 1: 14 usec in iter 4827
401489a0 1: 15 usec in iter 4861
401489a0 1: 15 usec in iter 4869
401489a0 1: 14 usec in iter 4890
401489a0 1: 15 usec in iter 4910
401489a0 1: 15 usec in iter 4943
401489a0 1: 14 usec in iter 4967
401489a0 1: 15 usec in iter 4969
401489a0 1: 15 usec in iter 4980
401489a0 1: 15 usec in iter 4985
401489a0 1: 16 usec in iter 5008
401489a0 1: 16 usec in iter 5042
401489a0 1: 15 usec in iter 5049
401489a0 1: 15 usec in iter 5055
401489a0 1: 15 usec in iter 5064
401489a0 1: 16 usec in iter 5071
401489a0 1: 16 usec in iter 5091
401489a0 1: 15 usec in iter 5117
401489a0 1: 15 usec in iter 5136
401489a0 1: 15 usec in iter 5162
401489a0 1: 15 usec in iter 5167
401489a0 1: 14 usec in iter 5180
401489a0 1: 15 usec in iter 5182
401489a0 1: 15 usec in iter 5193
401489a0 1: 14 usec in iter 5196
401489a0 1: 16 usec in iter 5206
401489a0 1: 14 usec in iter 5211
401489a0 1: 16 usec in iter 5221
401489a0 1: 15 usec in iter 5241
401489a0 1: 15 usec in iter 5272
401489a0 1: 54 usec in iter 5284
401489a0 1: 16 usec in iter 5288
401489a0 1: 15 usec in iter 5307
401489a0 1: 16 usec in iter 5337
401489a0 1: 15 usec in iter 5351
401489a0 1: 15 usec in iter 5352
401489a0 1: 16 usec in iter 5374
401489a0 1: 14 usec in iter 5409
401489a0 1: 15 usec in iter 5410
401489a0 1: 14 usec in iter 5442
401489a0 1: 14 usec in iter 5446
401489a0 1: 15 usec in iter 5465
401489a0 1: 14 usec in iter 5489
401489a0 1: 14 usec in iter 5518
401489a0 1: 14 usec in iter 5536
401489a0 1: 15 usec in iter 5563
401489a0 1: 53 usec in iter 5594
401489a0 1: 16 usec in iter 5610
401489a0 1: 15 usec in iter 5616
401489a0 1: 14 usec in iter 5626
401489a0 1: 15 usec in iter 5630
401489a0 1: 15 usec in iter 5662
401489a0 1: 15 usec in iter 5693
401489a0 1: 14 usec in iter 5699
401489a0 1: 14 usec in iter 5730
401489a0 1: 16 usec in iter 5754
401489a0 1: 15 usec in iter 5787
401489a0 1: 14 usec in iter 5789
401489a0 1: 15 usec in iter 5808
401489a0 1: 16 usec in iter 5809
401489a0 1: 16 usec in iter 5841
401489a0 1: 14 usec in iter 5849
401489a0 1: 14 usec in iter 5873
401489a0 1: 15 usec in iter 5887
401489a0 1: 14 usec in iter 5908
401489a0 1: 16 usec in iter 5937
401489a0 1: 15 usec in iter 5961
401489a0 1: 15 usec in iter 5982
401489a0 1: 15 usec in iter 5984
401489a0 1: 59 usec in iter 6004
401489a0 1: 14 usec in iter 6032
401489a0 1: 15 usec in iter 6051
401489a0 1: 15 usec in iter 6081
401489a0 1: 15 usec in iter 6112
401489a0 1: 15 usec in iter 6119
401489a0 1: 15 usec in iter 6136
401489a0 1: 60 usec in iter 6140
401489a0 1: 14 usec in iter 6167
401489a0 1: 56 usec in iter 6168
401489a0 1: 14 usec in iter 6179
401489a0 1: 13 usec in iter 6209
401489a0 1: 15 usec in iter 6227
401489a0 1: 14 usec in iter 6249
401489a0 1: 61 usec in iter 6250
401489a0 1: 14 usec in iter 6270
401489a0 1: 14 usec in iter 6291
401489a0 1: 13 usec in iter 6312
401489a0 1: 16 usec in iter 6331
401489a0 1: 14 usec in iter 6358
401489a0 1: 53 usec in iter 6359
401489a0 1: 15 usec in iter 6368
401489a0 1: 14 usec in iter 6373
401489a0 1: 13 usec in iter 6391
401489a0 1: 15 usec in iter 6411
401489a0 1: 15 usec in iter 6432
401489a0 1: 15 usec in iter 6454
401489a0 1: 15 usec in iter 6476
401489a0 1: 15 usec in iter 6508
401489a0 1: 15 usec in iter 6545
401489a0 1: 14 usec in iter 6564
401489a0 1: 15 usec in iter 6581
401489a0 1: 15 usec in iter 6611
401489a0 1: 14 usec in iter 6641
401489a0 1: 14 usec in iter 6661
401489a0 1: 15 usec in iter 6680
401489a0 1: 16 usec in iter 6700
401489a0 1: 15 usec in iter 6728
401489a0 1: 14 usec in iter 6738
401489a0 1: 15 usec in iter 6758
401489a0 1: 14 usec in iter 6777
401489a0 1: 15 usec in iter 6782
401489a0 1: 15 usec in iter 6784
401489a0 1: 15 usec in iter 6799
401489a0 1: 15 usec in iter 6803
401489a0 1: 16 usec in iter 6817
401489a0 1: 15 usec in iter 6831
401489a0 1: 14 usec in iter 6840
401489a0 1: 15 usec in iter 6861
401489a0 1: 14 usec in iter 6893
401489a0 1: 15 usec in iter 6911
401489a0 1: 14 usec in iter 6935
401489a0 1: 16 usec in iter 6950
401489a0 1: 15 usec in iter 6976
401489a0 1: 54 usec in iter 6987
401489a0 1: 16 usec in iter 6989
401489a0 1: 15 usec in iter 7020
401489a0 1: 14 usec in iter 7043
401489a0 1: 15 usec in iter 7065
401489a0 1: 14 usec in iter 7097
401489a0 1: 14 usec in iter 7110
401489a0 1: 16 usec in iter 7117
401489a0 1: 15 usec in iter 7126
401489a0 1: 15 usec in iter 7142
401489a0 1: 14 usec in iter 7153
401489a0 1: 14 usec in iter 7157
401489a0 1: 15 usec in iter 7160
401489a0 1: 15 usec in iter 7187
401489a0 1: 15 usec in iter 7223
401489a0 1: 15 usec in iter 7251
401489a0 1: 15 usec in iter 7271
401489a0 1: 15 usec in iter 7277
401489a0 1: 15 usec in iter 7298
401489a0 1: 14 usec in iter 7301
401489a0 1: 15 usec in iter 7334
401489a0 1: 16 usec in iter 7359
401489a0 1: 15 usec in iter 7378
401489a0 1: 15 usec in iter 7404
401489a0 1: 17 usec in iter 7417
401489a0 1: 17 usec in iter 7420
401489a0 1: 15 usec in iter 7431
401489a0 1: 16 usec in iter 7437
401489a0 1: 16 usec in iter 7451
401489a0 1: 16 usec in iter 7478
401489a0 1: 15 usec in iter 7502
401489a0 1: 15 usec in iter 7503
401489a0 1: 14 usec in iter 7535
401489a0 1: 15 usec in iter 7556
401489a0 1: 15 usec in iter 7558
401489a0 1: 52 usec in iter 7578
401489a0 1: 16 usec in iter 7583
401489a0 1: 13 usec in iter 7596
401489a0 1: 15 usec in iter 7618
401489a0 1: 14 usec in iter 7623
401489a0 1: 16 usec in iter 7624
401489a0 1: 15 usec in iter 7626
401489a0 1: 15 usec in iter 7636
401489a0 1: 16 usec in iter 7638
401489a0 1: 16 usec in iter 7661
401489a0 1: 16 usec in iter 7690
401489a0 1: 14 usec in iter 7716
401489a0 1: 16 usec in iter 7739
401489a0 1: 15 usec in iter 7767
401489a0 1: 15 usec in iter 7776
401489a0 1: 15 usec in iter 7815
401489a0 1: 16 usec in iter 7844
401489a0 1: 15 usec in iter 7875
401489a0 1: 15 usec in iter 7891
401489a0 1: 14 usec in iter 7893
401489a0 1: 14 usec in iter 7930
401489a0 1: 15 usec in iter 7937
401489a0 1: 14 usec in iter 7975
401489a0 1: 16 usec in iter 8001
401489a0 1: 14 usec in iter 8039
401489a0 1: 14 usec in iter 8044
401489a0 1: 15 usec in iter 8054
401489a0 1: 15 usec in iter 8080
401489a0 1: 15 usec in iter 8113
401489a0 1: 16 usec in iter 8120
401489a0 1: 15 usec in iter 8159
401489a0 1: 15 usec in iter 8174
401489a0 1: 16 usec in iter 8210
401489a0 1: 14 usec in iter 8226
401489a0 1: 55 usec in iter 8261
401489a0 1: 16 usec in iter 8291
401489a0 1: 15 usec in iter 8319
401489a0 1: 15 usec in iter 8322
401489a0 1: 14 usec in iter 8348
401489a0 1: 14 usec in iter 8359
401489a0 1: 14 usec in iter 8375
401489a0 1: 15 usec in iter 8401
401489a0 1: 15 usec in iter 8422
401489a0 1: 16 usec in iter 8437
401489a0 1: 15 usec in iter 8457
401489a0 1: 15 usec in iter 8485
401489a0 1: 14 usec in iter 8511
401489a0 1: 15 usec in iter 8512
401489a0 1: 16 usec in iter 8536
401489a0 1: 15 usec in iter 8540
401489a0 1: 15 usec in iter 8570
401489a0 1: 15 usec in iter 8609
401489a0 1: 15 usec in iter 8637
401489a0 1: 15 usec in iter 8648
401489a0 1: 15 usec in iter 8670
401489a0 1: 14 usec in iter 8673
401489a0 1: 16 usec in iter 8714
401489a0 1: 15 usec in iter 8729
401489a0 1: 14 usec in iter 8750
401489a0 1: 15 usec in iter 8787
401489a0 1: 14 usec in iter 8803
401489a0 1: 16 usec in iter 8816
401489a0 1: 15 usec in iter 8838
401489a0 1: 14 usec in iter 8843
401489a0 1: 15 usec in iter 8844
401489a0 1: 16 usec in iter 8865
401489a0 1: 17 usec in iter 8870
401489a0 1: 16 usec in iter 8879
401489a0 1: 16 usec in iter 8896
401489a0 1: 15 usec in iter 8937
401489a0 1: 15 usec in iter 8949
401489a0 1: 15 usec in iter 8960
401489a0 1: 15 usec in iter 8994
401489a0 1: 16 usec in iter 9027
401489a0 1: 17 usec in iter 9040
401489a0 1: 15 usec in iter 9046
401489a0 1: 15 usec in iter 9050
401489a0 1: 14 usec in iter 9057
401489a0 1: 16 usec in iter 9058
401489a0 1: 14 usec in iter 9075
401489a0 1: 15 usec in iter 9076
401489a0 1: 16 usec in iter 9099
401489a0 1: 14 usec in iter 9139
401489a0 1: 15 usec in iter 9158
401489a0 1: 15 usec in iter 9186
401489a0 1: 14 usec in iter 9212
401489a0 1: 15 usec in iter 9238
401489a0 1: 16 usec in iter 9269
401489a0 1: 17 usec in iter 9275
401489a0 1: 14 usec in iter 9298
401489a0 1: 16 usec in iter 9312
401489a0 1: 14 usec in iter 9325
401489a0 1: 15 usec in iter 9345
401489a0 1: 16 usec in iter 9362
401489a0 1: 16 usec in iter 9382
401489a0 1: 16 usec in iter 9387
401489a0 1: 15 usec in iter 9424
401489a0 1: 52 usec in iter 9435
401489a0 1: 15 usec in iter 9438
401489a0 1: 15 usec in iter 9481
401489a0 1: 15 usec in iter 9491
401489a0 1: 15 usec in iter 9499
401489a0 1: 16 usec in iter 9535
401489a0 1: 15 usec in iter 9554
401489a0 1: 14 usec in iter 9561
401489a0 1: 14 usec in iter 9576
401489a0 1: 15 usec in iter 9614
401489a0 1: 15 usec in iter 9640
401489a0 1: 14 usec in iter 9668
401489a0 1: 15 usec in iter 9700
401489a0 1: 16 usec in iter 9705
401489a0 1: 15 usec in iter 9729
401489a0 1: 15 usec in iter 9738
401489a0 1: 15 usec in iter 9777
401489a0 1: 15 usec in iter 9816
401489a0 1: 16 usec in iter 9822
401489a0 1: 15 usec in iter 9828
401489a0 1: 17 usec in iter 9870
401489a0 1: 15 usec in iter 9911
401489a0 1: 15 usec in iter 9916
401489a0 1: 15 usec in iter 9956
401489a0 1: 15 usec in iter 9991
401489a0 1: raw totaltime = 0.462843
401489a0 1: per_iter = 0.00017897, SampleOverhead = 3.29e-06
401489a0 1: adj totaltime = 2.12368
401489a0 1: sampling = 0
401489a0 1: starttime = 0/000000
401489a0 1: counter = 0/462843
401489a0 1: firsttuple = 0.331616
401489a0 1: tuplecount = 10000
401489a0 1: itercount = 10001
401489a0 1: samplecount = 721
401489a0 1: nextsample = 10018.7
401489a0 1: startup = 0.331616
401489a0 1: total = 2.12368
401489a0 1: ntuples = 10000