On Wed, Nov 18, 2015 at 3:29 PM, Peter Geoghegan <p...@heroku.com> wrote: > On Wed, Nov 18, 2015 at 10:31 AM, Jeff Janes <jeff.ja...@gmail.com> wrote: > >> I agree we don't want to optimize for low memory, but I don't think we >> should throw it under the bus, either. Right now we are effectively >> saying the CPU-cache problems with the heap start exceeding the larger >> run size benefits at 64kb (the smallest allowed setting for work_mem). >> While any number we pick is going to be a guess that won't apply to >> all hardware, surely we can come up with a guess better than 64kb. >> Like, 8 MB, say. If available memory for the sort is 8MB or smaller >> and the predicted size anticipates a multipass merge, then we can use >> the heap method rather than the quicksort method. Would a rule like >> that complicate things much? > > I'm already using replacement selection for the first run when it is > predicted by my new ad-hoc cost model that we can get away with a > "quicksort with spillover", avoiding almost all I/O. We only > incrementally spill as many tuples as needed right now, but it would > be pretty easy to not quicksort the remaining tuples, but continue to > incrementally spill everything. So no, it wouldn't be too hard to hang > on to the old behavior sometimes, if it looked worthwhile. > > In principle, I have no problem with doing that. Through testing, I > cannot see any actual upside, though. Perhaps I just missed something. > Even 8MB is enough to avoid the multipass merge in the event of a > surprisingly high volume of data (my work laptop is elsewhere, so I > don't have my notes on this in front of me, but I figured out the > crossover point for a couple of cases).
For me very large sorts (100,000,000 ints) with work_mem below 4MB do better with unpatched than with your patch series, by about 5%. Not a big deal, but also if it is easy to keep the old behavior then I think we should. Yes, it is dumb to do large sorts with work_mem below 4MB, but if you have canned apps which do a mixture of workloads it is not so easy to micromanage their work_mem. Especially as there are no easy tools that let me as the DBA say "if you connect from this IP address, you get this work_mem". I didn't collect trace_sort on those ones because of the high volume it would generate. > >>> In theory, the answer could be "yes", but it seems highly unlikely. >>> Not only is very little memory required to avoid a multi-pass merge >>> step, but as described above the amount required grows very slowly >>> relative to linear growth in input. I propose to add a >>> checkpoint_warning style warning (with a checkpoint_warning style GUC >>> to control it). >> >> I'm skeptical about a warning for this. > > Other systems expose this explicitly, and, as I said, say in an > unqualified way that a multi-pass merge should be avoided. Maybe the > warning isn't the right way of communicating that message to the DBA > in detail, but I am confident that it ought to be communicated to the > DBA fairly clearly. I thinking about how many other places in the code could justify a similar type of warning "If you just gave me 15% more memory, this hash join would be much faster", and what that would make the logs look like if future work went along with this precedence. If there were some mechanism to put the warning in a system view counter instead of the log file, that would be much cleaner. Or a way to separate the server log file into streams. But since we don't have those, I guess I can't really object much to the proposed behavior. > >> One idea would be to stop and write out a just-sorted partition >> whenever that partition is contiguous to the already-written portion. >> If the qsort is tweaked to recurse preferentially into the left >> partition first, this would result in tuples being written out at a >> pretty study pace. If the qsort was unbalanced and the left partition >> was always the larger of the two, then that approach would have to be >> abandoned at some point. But I think there are already defenses >> against that, and at worst you would give up and revert to the >> sort-them-all then write-them-all behavior. > > Seems kind of invasive. I agree, but I wonder if it won't become much more important at 30GB of work_mem. Of course if there is no reason to ever set work_mem that high, then it wouldn't matter--but there is always a reason to do so, if you have so much memory to spare. So better than that invasive work, I guess would be to make sort use less than work_mem if it gets no benefit from using all of it. Anyway, ideas for future work, either way. > >> Overall this is very nice. Doing some real world index builds of >> short text (~20 bytes ascii) identifiers, I could easily get speed ups >> of 40% with your patch if I followed the philosophy of "give it as >> much maintenance_work_mem as I can afford". If I fine-tuned the >> maintenance_work_mem so that it was optimal for each sort method, then >> the speed up quite a bit less, only 22%. But 22% is still very >> worthwhile, and who wants to spend their time fine-tuning the memory >> use for every index build? > > Thanks, but I expected better than that. Was it a collated text > column? The C collation will put the patch in a much better light > (more strcoll() calls are needed with this new approach -- it's still > well worth it, but it is a downside that makes collated text not > especially sympathetic). Just sorting on an integer attribute is also > a good sympathetic case, FWIW. It was UTF8 encoded (although all characters were actually ASCII), but C collated. I've never seen improvements of 3 fold or more like you saw, under any conditions, so I wonder if your test machine doesn't have unusually slow main memory. > > How much time did the sort take in each case? How many runs? How much > time was spent merging? trace_sort output is very interesting here. My largest test, which took my true table and extrapolated it out for a few years growth, had about 500,000,000 rows. At 3GB maintainance_work_mem, it took 13 runs patched and 7 runs unpatched to build the index, with timings of 3168.66 sec and 5713.07 sec. The final merging is intermixed with whatever other work goes on to build the actual index files out of the sorted data, so I don't know exactly what the timing of just the merge part was. But it was certainly a minority of the time, even if you assume the actual index build were free. For the patched code, the majority of the time goes to the quick sorting stages. When I test each version of the code at its own most efficient maintenance_work_mem, I get 3007.2 seconds at 1GB for patched and 3836.46 seconds at 64MB for unpatched. I'm attaching the trace_sort output from the client log for all 4 of those scenarios. "sort_0005" means all 5 of your patches were applied, "origin" means none of them were. Cheers, Jeff
sort_0005 1GB LOG: begin index sort: unique = f, workMem = 1048576, randomAccess = f LOG: bttext_abbrev: abbrev_distinct after 160: 1.000489 (key_distinct: 40.802210, norm_abbrev_card: 0.006253, prop_card: 0.200000) LOG: bttext_abbrev: aborted abbreviation at 160 (abbrev_distinct: 1.000489, key_distinct: 40.802210, prop_card: 0.200000) LOG: switching to external sort with 3745 tapes: CPU 2.09s/5.79u sec elapsed 8.60 sec LOG: hybrid sort-merge strategy used at row 14913080 crossover 0.750 (est 486040960.00 rows 32.59 runs) LOG: starting quicksort of run 1: CPU 2.09s/5.79u sec elapsed 8.61 sec LOG: finished quicksorting run 1: CPU 2.10s/30.07u sec elapsed 32.93 sec LOG: finished writing run 1 to tape 0: CPU 2.97s/31.42u sec elapsed 35.99 sec LOG: starting quicksort of run 2: CPU 3.61s/36.07u sec elapsed 42.40 sec LOG: finished quicksorting run 2: CPU 3.62s/68.09u sec elapsed 74.47 sec LOG: finished writing run 2 to tape 1: CPU 4.27s/69.65u sec elapsed 76.85 sec LOG: starting quicksort of run 3: CPU 4.90s/75.17u sec elapsed 83.80 sec LOG: finished quicksorting run 3: CPU 4.91s/113.97u sec elapsed 122.66 sec LOG: finished writing run 3 to tape 2: CPU 5.47s/115.48u sec elapsed 124.86 sec LOG: starting quicksort of run 4: CPU 6.30s/122.80u sec elapsed 135.05 sec LOG: finished quicksorting run 4: CPU 6.30s/165.40u sec elapsed 177.70 sec LOG: finished writing run 4 to tape 3: CPU 6.93s/167.13u sec elapsed 180.33 sec LOG: starting quicksort of run 5: CPU 7.59s/174.42u sec elapsed 190.40 sec LOG: finished quicksorting run 5: CPU 7.59s/218.81u sec elapsed 234.84 sec LOG: finished writing run 5 to tape 4: CPU 8.33s/220.64u sec elapsed 237.43 sec LOG: starting quicksort of run 6: CPU 8.98s/227.39u sec elapsed 246.48 sec LOG: finished quicksorting run 6: CPU 8.98s/271.59u sec elapsed 290.72 sec LOG: finished writing run 6 to tape 5: CPU 9.59s/273.25u sec elapsed 293.03 sec LOG: starting quicksort of run 7: CPU 10.40s/279.34u sec elapsed 301.35 sec LOG: finished quicksorting run 7: CPU 10.40s/325.03u sec elapsed 347.12 sec LOG: finished writing run 7 to tape 6: CPU 11.11s/327.27u sec elapsed 350.09 sec LOG: starting quicksort of run 8: CPU 11.91s/334.96u sec elapsed 359.58 sec LOG: finished quicksorting run 8: CPU 11.92s/379.44u sec elapsed 404.12 sec LOG: finished writing run 8 to tape 7: CPU 12.54s/381.20u sec elapsed 406.70 sec LOG: starting quicksort of run 9: CPU 13.42s/388.59u sec elapsed 416.47 sec LOG: finished quicksorting run 9: CPU 13.44s/433.70u sec elapsed 461.65 sec LOG: finished writing run 9 to tape 8: CPU 14.11s/435.50u sec elapsed 464.33 sec LOG: starting quicksort of run 10: CPU 14.75s/442.15u sec elapsed 474.57 sec LOG: finished quicksorting run 10: CPU 14.75s/486.68u sec elapsed 519.23 sec LOG: finished writing run 10 to tape 9: CPU 15.35s/488.34u sec elapsed 521.54 sec LOG: starting quicksort of run 11: CPU 16.05s/495.35u sec elapsed 530.41 sec LOG: finished quicksorting run 11: CPU 16.08s/540.35u sec elapsed 575.50 sec LOG: finished writing run 11 to tape 10: CPU 16.63s/542.10u sec elapsed 577.82 sec LOG: starting quicksort of run 12: CPU 17.14s/548.09u sec elapsed 585.05 sec LOG: finished quicksorting run 12: CPU 17.14s/592.99u sec elapsed 630.00 sec LOG: finished writing run 12 to tape 11: CPU 17.77s/594.63u sec elapsed 632.26 sec LOG: starting quicksort of run 13: CPU 18.34s/600.82u sec elapsed 639.82 sec LOG: finished quicksorting run 13: CPU 18.34s/645.65u sec elapsed 684.71 sec LOG: finished writing run 13 to tape 12: CPU 18.94s/647.30u sec elapsed 687.14 sec LOG: starting quicksort of run 14: CPU 19.47s/653.11u sec elapsed 694.16 sec LOG: finished quicksorting run 14: CPU 19.47s/698.06u sec elapsed 739.19 sec LOG: finished writing run 14 to tape 13: CPU 20.25s/700.17u sec elapsed 742.09 sec LOG: starting quicksort of run 15: CPU 21.04s/707.00u sec elapsed 754.26 sec LOG: finished quicksorting run 15: CPU 21.05s/752.06u sec elapsed 799.39 sec LOG: finished writing run 15 to tape 14: CPU 21.63s/753.73u sec elapsed 801.67 sec LOG: starting quicksort of run 16: CPU 22.17s/759.56u sec elapsed 809.49 sec LOG: finished quicksorting run 16: CPU 22.18s/804.91u sec elapsed 854.92 sec LOG: finished writing run 16 to tape 15: CPU 22.83s/806.66u sec elapsed 857.46 sec LOG: starting quicksort of run 17: CPU 23.62s/814.74u sec elapsed 868.66 sec LOG: finished quicksorting run 17: CPU 23.65s/858.07u sec elapsed 912.09 sec LOG: finished writing run 17 to tape 16: CPU 24.26s/859.75u sec elapsed 914.64 sec LOG: starting quicksort of run 18: CPU 24.82s/866.20u sec elapsed 922.50 sec LOG: finished quicksorting run 18: CPU 24.86s/911.32u sec elapsed 967.77 sec LOG: finished writing run 18 to tape 17: CPU 25.47s/912.92u sec elapsed 970.02 sec LOG: starting quicksort of run 19: CPU 26.00s/919.12u sec elapsed 977.72 sec LOG: finished quicksorting run 19: CPU 26.03s/963.08u sec elapsed 1021.78 sec LOG: finished writing run 19 to tape 18: CPU 26.66s/964.56u sec elapsed 1023.93 sec LOG: starting quicksort of run 20: CPU 27.32s/971.25u sec elapsed 1032.17 sec LOG: finished quicksorting run 20: CPU 27.36s/1015.80u sec elapsed 1076.85 sec LOG: finished writing run 20 to tape 19: CPU 27.94s/1017.31u sec elapsed 1079.03 sec LOG: starting quicksort of run 21: CPU 28.54s/1023.57u sec elapsed 1088.26 sec LOG: finished quicksorting run 21: CPU 28.54s/1066.25u sec elapsed 1130.99 sec LOG: finished writing run 21 to tape 20: CPU 29.20s/1067.92u sec elapsed 1133.32 sec LOG: starting quicksort of run 22: CPU 29.86s/1074.29u sec elapsed 1142.35 sec LOG: finished quicksorting run 22: CPU 29.86s/1118.67u sec elapsed 1186.77 sec LOG: finished writing run 22 to tape 21: CPU 30.50s/1120.37u sec elapsed 1189.28 sec LOG: starting quicksort of run 23: CPU 31.13s/1126.93u sec elapsed 1197.77 sec LOG: finished quicksorting run 23: CPU 31.13s/1169.86u sec elapsed 1240.75 sec LOG: finished writing run 23 to tape 22: CPU 31.83s/1171.49u sec elapsed 1243.09 sec LOG: starting quicksort of run 24: CPU 32.43s/1177.56u sec elapsed 1250.58 sec LOG: finished quicksorting run 24: CPU 32.43s/1220.30u sec elapsed 1293.38 sec LOG: finished writing run 24 to tape 23: CPU 33.04s/1221.81u sec elapsed 1295.60 sec LOG: starting quicksort of run 25: CPU 33.61s/1227.52u sec elapsed 1302.55 sec LOG: finished quicksorting run 25: CPU 33.61s/1270.66u sec elapsed 1345.76 sec LOG: finished writing run 25 to tape 24: CPU 34.16s/1272.17u sec elapsed 1347.86 sec LOG: starting quicksort of run 26: CPU 34.71s/1278.20u sec elapsed 1357.61 sec LOG: finished quicksorting run 26: CPU 34.72s/1320.86u sec elapsed 1400.32 sec LOG: finished writing run 26 to tape 25: CPU 35.31s/1322.38u sec elapsed 1402.47 sec LOG: starting quicksort of run 27: CPU 35.84s/1328.09u sec elapsed 1409.46 sec LOG: finished quicksorting run 27: CPU 35.85s/1371.02u sec elapsed 1452.45 sec LOG: finished writing run 27 to tape 26: CPU 36.44s/1372.53u sec elapsed 1454.59 sec LOG: starting quicksort of run 28: CPU 37.09s/1378.87u sec elapsed 1462.29 sec LOG: finished quicksorting run 28: CPU 37.09s/1420.58u sec elapsed 1504.05 sec LOG: finished writing run 28 to tape 27: CPU 37.69s/1422.10u sec elapsed 1506.19 sec LOG: starting quicksort of run 29: CPU 38.32s/1428.54u sec elapsed 1514.08 sec LOG: finished quicksorting run 29: CPU 38.35s/1473.13u sec elapsed 1558.77 sec LOG: finished writing run 29 to tape 28: CPU 39.02s/1474.77u sec elapsed 1561.44 sec LOG: starting quicksort of run 30: CPU 39.63s/1481.25u sec elapsed 1569.38 sec LOG: finished quicksorting run 30: CPU 39.66s/1523.71u sec elapsed 1611.94 sec LOG: finished writing run 30 to tape 29: CPU 40.26s/1525.24u sec elapsed 1614.07 sec LOG: starting quicksort of run 31: CPU 40.89s/1531.96u sec elapsed 1622.24 sec LOG: finished quicksorting run 31: CPU 40.90s/1574.46u sec elapsed 1664.79 sec LOG: finished writing run 31 to tape 30: CPU 41.50s/1576.03u sec elapsed 1666.96 sec LOG: starting quicksort of run 32: CPU 42.23s/1582.44u sec elapsed 1676.15 sec LOG: finished quicksorting run 32: CPU 42.25s/1624.39u sec elapsed 1718.18 sec LOG: finished writing run 32 to tape 31: CPU 42.85s/1625.92u sec elapsed 1720.38 sec LOG: starting quicksort of run 33: CPU 43.50s/1632.36u sec elapsed 1728.26 sec LOG: finished quicksorting run 33: CPU 43.50s/1675.37u sec elapsed 1771.33 sec LOG: finished writing run 33 to tape 32: CPU 44.12s/1676.90u sec elapsed 1773.51 sec LOG: starting quicksort of run 34: CPU 44.71s/1682.99u sec elapsed 1781.00 sec LOG: finished quicksorting run 34: CPU 44.72s/1726.70u sec elapsed 1824.77 sec LOG: finished writing run 34 to tape 33: CPU 45.31s/1728.19u sec elapsed 1827.00 sec LOG: starting quicksort of run 35: CPU 46.00s/1734.36u sec elapsed 1834.61 sec LOG: finished quicksorting run 35: CPU 46.01s/1777.11u sec elapsed 1877.41 sec LOG: finished writing run 35 to tape 34: CPU 46.60s/1778.64u sec elapsed 1879.54 sec LOG: starting quicksort of run 36: CPU 47.14s/1784.31u sec elapsed 1889.35 sec LOG: finished quicksorting run 36: CPU 47.14s/1830.15u sec elapsed 1935.25 sec LOG: finished writing run 36 to tape 35: CPU 47.70s/1831.67u sec elapsed 1937.41 sec LOG: starting quicksort of run 37: CPU 48.35s/1838.25u sec elapsed 1945.48 sec LOG: finished quicksorting run 37: CPU 48.36s/1880.10u sec elapsed 1987.39 sec LOG: finished writing run 37 to tape 36: CPU 48.91s/1881.64u sec elapsed 1989.49 sec LOG: performsort starting: CPU 49.06s/1883.45u sec elapsed 1992.32 sec LOG: starting quicksort of run 38: CPU 49.06s/1883.45u sec elapsed 1992.32 sec LOG: finished quicksorting run 38: CPU 49.06s/1892.95u sec elapsed 2001.83 sec LOG: finished writing run 38 to tape 37: CPU 49.23s/1893.32u sec elapsed 2002.37 sec LOG: performsort done (except 38-way final merge): CPU 50.36s/1894.23u sec elapsed 2007.52 sec LOG: external sort ended, 2137953 disk blocks used: CPU 136.95s/2647.33u sec elapsed 3005.87 sec LOG: duration: 3007200.316 ms CPU 137.63s/2647.34u sec elapsed 3007.20 sec
origin 64MB LOG: begin index sort: unique = f, workMem = 65536, randomAccess = f LOG: bttext_abbrev: abbrev_distinct after 160: 1.000489 (key_distinct: 40.802210, norm_abbrev_card: 0.006253, prop_card: 0.200000) LOG: bttext_abbrev: aborted abbreviation at 160 (abbrev_distinct: 1.000489, key_distinct: 40.802210, prop_card: 0.200000) LOG: switching to external sort with 234 tapes: CPU 0.26s/0.44u sec elapsed 0.83 sec LOG: finished writing run 1 to tape 0: CPU 0.49s/5.87u sec elapsed 6.65 sec LOG: finished writing run 2 to tape 1: CPU 0.71s/11.82u sec elapsed 12.97 sec LOG: finished writing run 3 to tape 2: CPU 1.24s/28.24u sec elapsed 29.94 sec LOG: finished writing run 4 to tape 3: CPU 1.57s/37.57u sec elapsed 40.96 sec LOG: finished writing run 5 to tape 4: CPU 1.75s/43.16u sec elapsed 46.74 sec LOG: finished writing run 6 to tape 5: CPU 1.95s/49.06u sec elapsed 52.84 sec LOG: finished writing run 7 to tape 6: CPU 2.22s/57.80u sec elapsed 61.86 sec LOG: finished writing run 8 to tape 7: CPU 2.41s/63.35u sec elapsed 67.95 sec LOG: finished writing run 9 to tape 8: CPU 2.64s/71.03u sec elapsed 75.89 sec LOG: finished writing run 10 to tape 9: CPU 2.85s/77.46u sec elapsed 82.53 sec LOG: finished writing run 11 to tape 10: CPU 3.04s/83.73u sec elapsed 89.00 sec LOG: finished writing run 12 to tape 11: CPU 3.27s/90.78u sec elapsed 96.47 sec LOG: finished writing run 13 to tape 12: CPU 3.47s/96.75u sec elapsed 102.65 sec LOG: finished writing run 14 to tape 13: CPU 3.73s/104.01u sec elapsed 110.20 sec LOG: finished writing run 15 to tape 14: CPU 3.96s/110.50u sec elapsed 116.94 sec LOG: finished writing run 16 to tape 15: CPU 4.15s/115.75u sec elapsed 122.38 sec LOG: finished writing run 17 to tape 16: CPU 4.67s/131.18u sec elapsed 138.54 sec LOG: finished writing run 18 to tape 17: CPU 4.79s/135.15u sec elapsed 142.64 sec LOG: finished writing run 19 to tape 18: CPU 4.98s/141.74u sec elapsed 149.59 sec LOG: finished writing run 20 to tape 19: CPU 5.23s/149.24u sec elapsed 157.68 sec LOG: finished writing run 21 to tape 20: CPU 5.74s/166.04u sec elapsed 175.26 sec LOG: finished writing run 22 to tape 21: CPU 6.01s/174.98u sec elapsed 184.48 sec LOG: finished writing run 23 to tape 22: CPU 6.22s/180.58u sec elapsed 190.30 sec LOG: finished writing run 24 to tape 23: CPU 6.44s/187.15u sec elapsed 197.14 sec LOG: finished writing run 25 to tape 24: CPU 6.76s/196.57u sec elapsed 207.12 sec LOG: finished writing run 26 to tape 25: CPU 6.95s/202.16u sec elapsed 212.91 sec LOG: finished writing run 27 to tape 26: CPU 7.20s/209.60u sec elapsed 220.60 sec LOG: finished writing run 28 to tape 27: CPU 7.41s/215.73u sec elapsed 226.96 sec LOG: finished writing run 29 to tape 28: CPU 7.64s/222.10u sec elapsed 233.60 sec LOG: finished writing run 30 to tape 29: CPU 7.84s/228.67u sec elapsed 240.38 sec LOG: finished writing run 31 to tape 30: CPU 8.05s/234.92u sec elapsed 247.74 sec LOG: finished writing run 32 to tape 31: CPU 8.28s/241.90u sec elapsed 254.96 sec LOG: finished writing run 33 to tape 32: CPU 8.49s/248.35u sec elapsed 261.64 sec LOG: finished writing run 34 to tape 33: CPU 8.67s/253.81u sec elapsed 267.53 sec LOG: finished writing run 35 to tape 34: CPU 9.16s/269.33u sec elapsed 283.56 sec LOG: finished writing run 36 to tape 35: CPU 9.29s/273.33u sec elapsed 287.74 sec LOG: finished writing run 37 to tape 36: CPU 9.51s/279.84u sec elapsed 294.87 sec LOG: finished writing run 38 to tape 37: CPU 9.76s/286.61u sec elapsed 302.09 sec LOG: finished writing run 39 to tape 38: CPU 10.32s/303.40u sec elapsed 320.49 sec LOG: finished writing run 40 to tape 39: CPU 10.58s/312.30u sec elapsed 329.70 sec LOG: finished writing run 41 to tape 40: CPU 10.77s/317.50u sec elapsed 335.10 sec LOG: finished writing run 42 to tape 41: CPU 10.95s/323.19u sec elapsed 340.98 sec LOG: finished writing run 43 to tape 42: CPU 11.25s/332.24u sec elapsed 350.55 sec LOG: finished writing run 44 to tape 43: CPU 11.45s/338.10u sec elapsed 356.72 sec LOG: finished writing run 45 to tape 44: CPU 11.67s/345.33u sec elapsed 364.30 sec LOG: finished writing run 46 to tape 45: CPU 11.87s/351.35u sec elapsed 370.57 sec LOG: finished writing run 47 to tape 46: CPU 12.09s/357.98u sec elapsed 377.65 sec LOG: finished writing run 48 to tape 47: CPU 12.29s/364.38u sec elapsed 384.27 sec LOG: finished writing run 49 to tape 48: CPU 12.46s/369.99u sec elapsed 390.08 sec LOG: finished writing run 50 to tape 49: CPU 12.69s/376.81u sec elapsed 397.15 sec LOG: finished writing run 51 to tape 50: CPU 12.95s/383.41u sec elapsed 404.01 sec LOG: finished writing run 52 to tape 51: CPU 13.14s/388.63u sec elapsed 409.69 sec LOG: finished writing run 53 to tape 52: CPU 13.61s/403.51u sec elapsed 425.08 sec LOG: finished writing run 54 to tape 53: CPU 13.75s/407.44u sec elapsed 429.20 sec LOG: finished writing run 55 to tape 54: CPU 14.03s/414.39u sec elapsed 436.60 sec LOG: finished writing run 56 to tape 55: CPU 14.28s/421.66u sec elapsed 444.39 sec LOG: finished writing run 57 to tape 56: CPU 14.81s/438.25u sec elapsed 461.89 sec LOG: finished writing run 58 to tape 57: CPU 15.07s/446.83u sec elapsed 470.77 sec LOG: finished writing run 59 to tape 58: CPU 15.26s/451.99u sec elapsed 476.12 sec LOG: finished writing run 60 to tape 59: CPU 15.45s/457.65u sec elapsed 482.05 sec LOG: finished writing run 61 to tape 60: CPU 15.76s/466.48u sec elapsed 491.50 sec LOG: finished writing run 62 to tape 61: CPU 15.95s/471.70u sec elapsed 496.92 sec LOG: finished writing run 63 to tape 62: CPU 16.19s/478.72u sec elapsed 504.19 sec LOG: finished writing run 64 to tape 63: CPU 16.36s/484.76u sec elapsed 510.41 sec LOG: finished writing run 65 to tape 64: CPU 16.58s/490.76u sec elapsed 516.98 sec LOG: finished writing run 66 to tape 65: CPU 16.82s/497.63u sec elapsed 524.10 sec LOG: finished writing run 67 to tape 66: CPU 17.01s/503.30u sec elapsed 529.97 sec LOG: finished writing run 68 to tape 67: CPU 17.21s/510.16u sec elapsed 537.18 sec LOG: finished writing run 69 to tape 68: CPU 17.42s/516.52u sec elapsed 544.84 sec LOG: finished writing run 70 to tape 69: CPU 17.61s/521.77u sec elapsed 551.28 sec LOG: finished writing run 71 to tape 70: CPU 18.11s/536.76u sec elapsed 566.79 sec LOG: finished writing run 72 to tape 71: CPU 18.25s/540.56u sec elapsed 570.75 sec LOG: finished writing run 73 to tape 72: CPU 18.48s/547.51u sec elapsed 578.37 sec LOG: finished writing run 74 to tape 73: CPU 18.72s/554.22u sec elapsed 585.55 sec LOG: finished writing run 75 to tape 74: CPU 19.24s/570.81u sec elapsed 603.87 sec LOG: finished writing run 76 to tape 75: CPU 19.51s/579.39u sec elapsed 612.80 sec LOG: finished writing run 77 to tape 76: CPU 19.68s/584.55u sec elapsed 618.15 sec LOG: finished writing run 78 to tape 77: CPU 19.89s/590.63u sec elapsed 624.57 sec LOG: finished writing run 79 to tape 78: CPU 20.19s/599.51u sec elapsed 633.80 sec LOG: finished writing run 80 to tape 79: CPU 20.35s/604.80u sec elapsed 639.25 sec LOG: finished writing run 81 to tape 80: CPU 20.59s/612.41u sec elapsed 647.12 sec LOG: finished writing run 82 to tape 81: CPU 20.81s/618.66u sec elapsed 653.87 sec LOG: finished writing run 83 to tape 82: CPU 21.03s/624.57u sec elapsed 660.04 sec LOG: finished writing run 84 to tape 83: CPU 21.23s/631.11u sec elapsed 666.80 sec LOG: finished writing run 85 to tape 84: CPU 21.42s/636.90u sec elapsed 672.80 sec LOG: finished writing run 86 to tape 85: CPU 21.66s/644.38u sec elapsed 680.53 sec LOG: finished writing run 87 to tape 86: CPU 21.88s/650.94u sec elapsed 687.59 sec LOG: finished writing run 88 to tape 87: CPU 22.06s/656.28u sec elapsed 693.16 sec LOG: finished writing run 89 to tape 88: CPU 22.54s/670.96u sec elapsed 708.40 sec LOG: finished writing run 90 to tape 89: CPU 22.69s/675.01u sec elapsed 712.62 sec LOG: finished writing run 91 to tape 90: CPU 22.91s/682.06u sec elapsed 719.91 sec LOG: finished writing run 92 to tape 91: CPU 23.13s/688.90u sec elapsed 727.18 sec LOG: finished writing run 93 to tape 92: CPU 23.65s/705.13u sec elapsed 744.60 sec LOG: finished writing run 94 to tape 93: CPU 23.90s/713.73u sec elapsed 753.46 sec LOG: finished writing run 95 to tape 94: CPU 24.08s/719.15u sec elapsed 759.08 sec LOG: finished writing run 96 to tape 95: CPU 24.33s/725.32u sec elapsed 765.75 sec LOG: finished writing run 97 to tape 96: CPU 24.60s/733.82u sec elapsed 774.53 sec LOG: finished writing run 98 to tape 97: CPU 24.77s/739.11u sec elapsed 780.00 sec LOG: finished writing run 99 to tape 98: CPU 25.01s/746.25u sec elapsed 787.40 sec LOG: finished writing run 100 to tape 99: CPU 25.20s/752.52u sec elapsed 793.87 sec LOG: finished writing run 101 to tape 100: CPU 25.42s/758.97u sec elapsed 800.85 sec LOG: finished writing run 102 to tape 101: CPU 25.61s/765.45u sec elapsed 807.53 sec LOG: finished writing run 103 to tape 102: CPU 25.80s/771.06u sec elapsed 813.34 sec LOG: finished writing run 104 to tape 103: CPU 26.02s/777.85u sec elapsed 820.36 sec LOG: finished writing run 105 to tape 104: CPU 26.26s/784.53u sec elapsed 827.54 sec LOG: finished writing run 106 to tape 105: CPU 26.42s/789.59u sec elapsed 832.78 sec LOG: finished writing run 107 to tape 106: CPU 26.90s/804.93u sec elapsed 849.78 sec LOG: finished writing run 108 to tape 107: CPU 27.03s/808.75u sec elapsed 853.75 sec LOG: finished writing run 109 to tape 108: CPU 27.22s/815.10u sec elapsed 860.30 sec LOG: finished writing run 110 to tape 109: CPU 27.42s/821.77u sec elapsed 867.23 sec LOG: finished writing run 111 to tape 110: CPU 28.00s/838.97u sec elapsed 886.20 sec LOG: finished writing run 112 to tape 111: CPU 28.27s/847.65u sec elapsed 895.16 sec LOG: finished writing run 113 to tape 112: CPU 28.43s/852.87u sec elapsed 900.55 sec LOG: finished writing run 114 to tape 113: CPU 28.63s/858.63u sec elapsed 906.76 sec LOG: finished writing run 115 to tape 114: CPU 28.89s/867.48u sec elapsed 915.88 sec LOG: finished writing run 116 to tape 115: CPU 29.07s/872.97u sec elapsed 921.56 sec LOG: finished writing run 117 to tape 116: CPU 29.30s/880.44u sec elapsed 929.30 sec LOG: finished writing run 118 to tape 117: CPU 29.53s/887.31u sec elapsed 937.95 sec LOG: finished writing run 119 to tape 118: CPU 29.72s/893.14u sec elapsed 943.98 sec LOG: finished writing run 120 to tape 119: CPU 29.93s/899.83u sec elapsed 950.90 sec LOG: finished writing run 121 to tape 120: CPU 30.13s/905.66u sec elapsed 956.94 sec LOG: finished writing run 122 to tape 121: CPU 30.37s/912.91u sec elapsed 964.74 sec LOG: finished writing run 123 to tape 122: CPU 30.61s/919.19u sec elapsed 971.28 sec LOG: finished writing run 124 to tape 123: CPU 30.77s/924.30u sec elapsed 976.55 sec LOG: finished writing run 125 to tape 124: CPU 31.25s/938.98u sec elapsed 991.74 sec LOG: finished writing run 126 to tape 125: CPU 31.38s/942.83u sec elapsed 995.73 sec LOG: finished writing run 127 to tape 126: CPU 31.59s/949.62u sec elapsed 1002.73 sec LOG: finished writing run 128 to tape 127: CPU 31.83s/956.50u sec elapsed 1010.13 sec LOG: finished writing run 129 to tape 128: CPU 32.33s/972.59u sec elapsed 1027.04 sec LOG: finished writing run 130 to tape 129: CPU 32.61s/981.60u sec elapsed 1036.34 sec LOG: finished writing run 131 to tape 130: CPU 32.84s/987.84u sec elapsed 1043.08 sec LOG: finished writing run 132 to tape 131: CPU 33.04s/993.53u sec elapsed 1048.99 sec LOG: finished writing run 133 to tape 132: CPU 33.32s/1002.17u sec elapsed 1057.95 sec LOG: finished writing run 134 to tape 133: CPU 33.50s/1007.40u sec elapsed 1063.37 sec LOG: finished writing run 135 to tape 134: CPU 33.75s/1014.67u sec elapsed 1071.12 sec LOG: finished writing run 136 to tape 135: CPU 33.97s/1020.92u sec elapsed 1077.60 sec LOG: finished writing run 137 to tape 136: CPU 34.16s/1026.73u sec elapsed 1083.62 sec LOG: finished writing run 138 to tape 137: CPU 34.38s/1033.14u sec elapsed 1090.25 sec LOG: finished writing run 139 to tape 138: CPU 34.58s/1038.72u sec elapsed 1096.04 sec LOG: finished writing run 140 to tape 139: CPU 34.83s/1045.78u sec elapsed 1103.63 sec LOG: finished writing run 141 to tape 140: CPU 35.05s/1052.09u sec elapsed 1110.19 sec LOG: finished writing run 142 to tape 141: CPU 35.21s/1057.17u sec elapsed 1115.46 sec LOG: finished writing run 143 to tape 142: CPU 35.70s/1072.15u sec elapsed 1131.06 sec LOG: finished writing run 144 to tape 143: CPU 35.82s/1076.01u sec elapsed 1135.04 sec LOG: finished writing run 145 to tape 144: CPU 36.02s/1082.39u sec elapsed 1142.67 sec LOG: finished writing run 146 to tape 145: CPU 36.23s/1089.21u sec elapsed 1150.15 sec LOG: finished writing run 147 to tape 146: CPU 36.77s/1106.11u sec elapsed 1167.76 sec LOG: finished writing run 148 to tape 147: CPU 37.07s/1115.26u sec elapsed 1177.88 sec LOG: finished writing run 149 to tape 148: CPU 37.27s/1120.68u sec elapsed 1183.55 sec LOG: finished writing run 150 to tape 149: CPU 37.47s/1126.33u sec elapsed 1189.41 sec LOG: finished writing run 151 to tape 150: CPU 37.74s/1134.72u sec elapsed 1198.11 sec LOG: finished writing run 152 to tape 151: CPU 37.90s/1139.95u sec elapsed 1203.51 sec LOG: finished writing run 153 to tape 152: CPU 38.18s/1147.57u sec elapsed 1211.76 sec LOG: finished writing run 154 to tape 153: CPU 38.37s/1153.60u sec elapsed 1217.99 sec LOG: finished writing run 155 to tape 154: CPU 38.56s/1159.45u sec elapsed 1224.04 sec LOG: finished writing run 156 to tape 155: CPU 38.77s/1165.88u sec elapsed 1230.69 sec LOG: finished writing run 157 to tape 156: CPU 38.93s/1171.53u sec elapsed 1236.51 sec LOG: finished writing run 158 to tape 157: CPU 39.19s/1179.14u sec elapsed 1244.66 sec LOG: finished writing run 159 to tape 158: CPU 39.44s/1185.50u sec elapsed 1251.41 sec LOG: finished writing run 160 to tape 159: CPU 39.60s/1190.65u sec elapsed 1256.75 sec LOG: finished writing run 161 to tape 160: CPU 40.09s/1205.63u sec elapsed 1272.32 sec LOG: finished writing run 162 to tape 161: CPU 40.26s/1209.78u sec elapsed 1276.65 sec LOG: finished writing run 163 to tape 162: CPU 40.52s/1216.75u sec elapsed 1284.12 sec LOG: finished writing run 164 to tape 163: CPU 40.73s/1223.47u sec elapsed 1291.06 sec LOG: finished writing run 165 to tape 164: CPU 41.26s/1239.82u sec elapsed 1308.28 sec LOG: finished writing run 166 to tape 165: CPU 41.54s/1248.64u sec elapsed 1317.78 sec LOG: finished writing run 167 to tape 166: CPU 41.73s/1253.78u sec elapsed 1323.12 sec LOG: finished writing run 168 to tape 167: CPU 41.91s/1259.48u sec elapsed 1329.01 sec LOG: finished writing run 169 to tape 168: CPU 42.20s/1267.88u sec elapsed 1337.70 sec LOG: finished writing run 170 to tape 169: CPU 42.39s/1273.10u sec elapsed 1343.39 sec LOG: finished writing run 171 to tape 170: CPU 42.62s/1280.37u sec elapsed 1350.90 sec LOG: finished writing run 172 to tape 171: CPU 42.82s/1286.37u sec elapsed 1357.12 sec LOG: finished writing run 173 to tape 172: CPU 43.04s/1292.44u sec elapsed 1363.41 sec LOG: finished writing run 174 to tape 173: CPU 43.27s/1299.00u sec elapsed 1370.21 sec LOG: finished writing run 175 to tape 174: CPU 43.46s/1304.67u sec elapsed 1376.32 sec LOG: finished writing run 176 to tape 175: CPU 43.66s/1311.56u sec elapsed 1383.43 sec LOG: finished writing run 177 to tape 176: CPU 43.85s/1318.06u sec elapsed 1390.12 sec LOG: finished writing run 178 to tape 177: CPU 44.04s/1323.45u sec elapsed 1395.70 sec LOG: finished writing run 179 to tape 178: CPU 44.51s/1338.53u sec elapsed 1411.36 sec LOG: finished writing run 180 to tape 179: CPU 44.66s/1342.32u sec elapsed 1415.29 sec LOG: finished writing run 181 to tape 180: CPU 44.91s/1349.07u sec elapsed 1422.56 sec LOG: finished writing run 182 to tape 181: CPU 45.11s/1355.71u sec elapsed 1429.41 sec LOG: finished writing run 183 to tape 182: CPU 45.64s/1372.43u sec elapsed 1448.37 sec LOG: finished writing run 184 to tape 183: CPU 45.91s/1381.29u sec elapsed 1458.98 sec LOG: finished writing run 185 to tape 184: CPU 46.10s/1386.66u sec elapsed 1464.56 sec LOG: finished writing run 186 to tape 185: CPU 46.31s/1392.51u sec elapsed 1470.80 sec LOG: finished writing run 187 to tape 186: CPU 46.60s/1401.34u sec elapsed 1481.02 sec LOG: finished writing run 188 to tape 187: CPU 46.79s/1406.82u sec elapsed 1486.72 sec LOG: finished writing run 189 to tape 188: CPU 47.04s/1413.94u sec elapsed 1494.10 sec LOG: finished writing run 190 to tape 189: CPU 47.23s/1420.04u sec elapsed 1500.40 sec LOG: finished writing run 191 to tape 190: CPU 47.40s/1426.04u sec elapsed 1506.58 sec LOG: finished writing run 192 to tape 191: CPU 47.63s/1432.74u sec elapsed 1513.87 sec LOG: finished writing run 193 to tape 192: CPU 47.86s/1438.69u sec elapsed 1520.06 sec LOG: finished writing run 194 to tape 193: CPU 48.07s/1445.54u sec elapsed 1527.14 sec LOG: finished writing run 195 to tape 194: CPU 48.28s/1451.88u sec elapsed 1533.70 sec LOG: finished writing run 196 to tape 195: CPU 48.44s/1457.01u sec elapsed 1538.99 sec LOG: finished writing run 197 to tape 196: CPU 48.97s/1472.59u sec elapsed 1555.15 sec LOG: finished writing run 198 to tape 197: CPU 49.11s/1476.41u sec elapsed 1559.13 sec LOG: finished writing run 199 to tape 198: CPU 49.34s/1483.58u sec elapsed 1566.85 sec LOG: finished writing run 200 to tape 199: CPU 49.56s/1490.47u sec elapsed 1574.00 sec LOG: finished writing run 201 to tape 200: CPU 50.04s/1506.70u sec elapsed 1590.82 sec LOG: finished writing run 202 to tape 201: CPU 50.34s/1515.93u sec elapsed 1601.01 sec LOG: finished writing run 203 to tape 202: CPU 50.54s/1521.36u sec elapsed 1606.82 sec LOG: finished writing run 204 to tape 203: CPU 50.74s/1527.08u sec elapsed 1612.75 sec LOG: finished writing run 205 to tape 204: CPU 51.01s/1535.58u sec elapsed 1621.76 sec LOG: finished writing run 206 to tape 205: CPU 51.22s/1541.13u sec elapsed 1627.52 sec LOG: finished writing run 207 to tape 206: CPU 51.50s/1548.93u sec elapsed 1635.63 sec LOG: finished writing run 208 to tape 207: CPU 51.71s/1555.27u sec elapsed 1642.18 sec LOG: finished writing run 209 to tape 208: CPU 51.90s/1561.12u sec elapsed 1648.23 sec LOG: finished writing run 210 to tape 209: CPU 52.15s/1568.22u sec elapsed 1655.82 sec LOG: finished writing run 211 to tape 210: CPU 52.35s/1573.84u sec elapsed 1661.65 sec LOG: finished writing run 212 to tape 211: CPU 52.58s/1581.16u sec elapsed 1669.21 sec LOG: finished writing run 213 to tape 212: CPU 52.79s/1587.48u sec elapsed 1675.75 sec LOG: finished writing run 214 to tape 213: CPU 52.96s/1592.59u sec elapsed 1681.04 sec LOG: finished writing run 215 to tape 214: CPU 53.42s/1607.31u sec elapsed 1696.25 sec LOG: finished writing run 216 to tape 215: CPU 53.57s/1611.14u sec elapsed 1700.24 sec LOG: finished writing run 217 to tape 216: CPU 53.80s/1617.91u sec elapsed 1707.52 sec LOG: finished writing run 218 to tape 217: CPU 54.02s/1624.57u sec elapsed 1714.41 sec LOG: finished writing run 219 to tape 218: CPU 54.52s/1640.97u sec elapsed 1731.34 sec LOG: finished writing run 220 to tape 219: CPU 54.80s/1649.58u sec elapsed 1742.07 sec LOG: finished writing run 221 to tape 220: CPU 54.98s/1654.81u sec elapsed 1747.60 sec LOG: finished writing run 222 to tape 221: CPU 55.18s/1660.65u sec elapsed 1753.81 sec LOG: finished writing run 223 to tape 222: CPU 55.43s/1669.34u sec elapsed 1762.84 sec LOG: finished writing run 224 to tape 223: CPU 55.62s/1674.93u sec elapsed 1768.99 sec LOG: finished writing run 225 to tape 224: CPU 55.86s/1681.95u sec elapsed 1776.25 sec LOG: finished writing run 226 to tape 225: CPU 56.05s/1687.95u sec elapsed 1782.46 sec LOG: finished writing run 227 to tape 226: CPU 56.24s/1693.79u sec elapsed 1788.50 sec LOG: finished writing run 228 to tape 227: CPU 56.50s/1700.53u sec elapsed 1795.74 sec LOG: finished writing run 229 to tape 228: CPU 56.67s/1706.16u sec elapsed 1801.56 sec LOG: finished writing run 230 to tape 229: CPU 56.87s/1713.04u sec elapsed 1808.65 sec LOG: finished writing run 231 to tape 230: CPU 57.08s/1719.37u sec elapsed 1815.20 sec LOG: finished writing run 232 to tape 231: CPU 57.25s/1724.49u sec elapsed 1820.51 sec LOG: finished writing run 233 to tape 232: CPU 57.72s/1739.43u sec elapsed 1835.99 sec LOG: finished writing run 234 to tape 0: CPU 57.86s/1743.36u sec elapsed 1840.32 sec LOG: finished writing run 235 to tape 1: CPU 58.09s/1750.02u sec elapsed 1847.24 sec LOG: finished writing run 236 to tape 2: CPU 58.32s/1756.99u sec elapsed 1854.45 sec LOG: finished writing run 237 to tape 3: CPU 58.86s/1773.33u sec elapsed 1871.56 sec LOG: finished writing run 238 to tape 4: CPU 59.21s/1783.56u sec elapsed 1882.15 sec LOG: finished writing run 239 to tape 5: CPU 59.41s/1788.71u sec elapsed 1887.51 sec LOG: finished writing run 240 to tape 6: CPU 59.63s/1794.87u sec elapsed 1894.00 sec LOG: finished writing run 241 to tape 7: CPU 59.92s/1803.56u sec elapsed 1903.72 sec LOG: finished writing run 242 to tape 8: CPU 60.12s/1809.00u sec elapsed 1909.46 sec LOG: finished writing run 243 to tape 9: CPU 60.35s/1816.04u sec elapsed 1916.79 sec LOG: finished writing run 244 to tape 10: CPU 60.57s/1822.47u sec elapsed 1923.46 sec LOG: finished writing run 245 to tape 11: CPU 60.78s/1828.30u sec elapsed 1929.50 sec LOG: finished writing run 246 to tape 12: CPU 61.03s/1835.12u sec elapsed 1936.81 sec LOG: finished writing run 247 to tape 13: CPU 61.22s/1840.72u sec elapsed 1942.60 sec LOG: finished writing run 248 to tape 14: CPU 61.48s/1848.27u sec elapsed 1950.44 sec LOG: finished writing run 249 to tape 15: CPU 61.70s/1854.60u sec elapsed 1957.00 sec LOG: finished writing run 250 to tape 16: CPU 61.86s/1859.97u sec elapsed 1962.59 sec LOG: finished writing run 251 to tape 17: CPU 62.34s/1875.31u sec elapsed 1978.44 sec LOG: finished writing run 252 to tape 18: CPU 62.49s/1879.22u sec elapsed 1982.83 sec LOG: finished writing run 253 to tape 19: CPU 62.71s/1885.98u sec elapsed 1989.83 sec LOG: finished writing run 254 to tape 20: CPU 62.95s/1893.40u sec elapsed 1997.51 sec LOG: finished writing run 255 to tape 21: CPU 63.60s/1912.87u sec elapsed 2017.90 sec LOG: finished writing run 256 to tape 22: CPU 63.88s/1921.42u sec elapsed 2026.74 sec LOG: finished writing run 257 to tape 23: CPU 64.05s/1926.80u sec elapsed 2032.30 sec LOG: finished writing run 258 to tape 24: CPU 64.26s/1932.71u sec elapsed 2038.71 sec LOG: finished writing run 259 to tape 25: CPU 64.58s/1942.09u sec elapsed 2050.45 sec LOG: finished writing run 260 to tape 26: CPU 64.77s/1947.72u sec elapsed 2056.34 sec LOG: finished writing run 261 to tape 27: CPU 65.02s/1954.67u sec elapsed 2063.54 sec LOG: finished writing run 262 to tape 28: CPU 65.22s/1961.10u sec elapsed 2070.19 sec LOG: finished writing run 263 to tape 29: CPU 65.51s/1969.11u sec elapsed 2079.10 sec LOG: finished writing run 264 to tape 30: CPU 65.78s/1976.79u sec elapsed 2087.07 sec LOG: finished writing run 265 to tape 31: CPU 65.97s/1982.45u sec elapsed 2092.96 sec LOG: finished writing run 266 to tape 32: CPU 66.21s/1989.34u sec elapsed 2100.09 sec LOG: finished writing run 267 to tape 33: CPU 66.46s/1995.73u sec elapsed 2106.89 sec LOG: finished writing run 268 to tape 34: CPU 66.63s/2001.00u sec elapsed 2112.33 sec LOG: finished writing run 269 to tape 35: CPU 67.13s/2016.61u sec elapsed 2128.85 sec LOG: finished writing run 270 to tape 36: CPU 67.26s/2020.47u sec elapsed 2132.87 sec LOG: finished writing run 271 to tape 37: CPU 67.47s/2026.82u sec elapsed 2139.46 sec LOG: finished writing run 272 to tape 38: CPU 67.69s/2033.50u sec elapsed 2146.40 sec LOG: finished writing run 273 to tape 39: CPU 68.21s/2049.83u sec elapsed 2163.63 sec LOG: finished writing run 274 to tape 40: CPU 68.50s/2058.39u sec elapsed 2172.50 sec LOG: finished writing run 275 to tape 41: CPU 68.66s/2063.61u sec elapsed 2177.88 sec LOG: finished writing run 276 to tape 42: CPU 68.83s/2069.26u sec elapsed 2183.72 sec LOG: finished writing run 277 to tape 43: CPU 69.13s/2078.07u sec elapsed 2193.25 sec LOG: finished writing run 278 to tape 44: CPU 69.30s/2083.33u sec elapsed 2198.91 sec LOG: finished writing run 279 to tape 45: CPU 69.53s/2090.78u sec elapsed 2206.61 sec LOG: finished writing run 280 to tape 46: CPU 69.72s/2096.89u sec elapsed 2212.93 sec LOG: finished writing run 281 to tape 47: CPU 69.90s/2102.81u sec elapsed 2219.32 sec LOG: finished writing run 282 to tape 48: CPU 70.13s/2109.33u sec elapsed 2226.08 sec LOG: finished writing run 283 to tape 49: CPU 70.34s/2115.11u sec elapsed 2232.09 sec LOG: finished writing run 284 to tape 50: CPU 70.60s/2122.47u sec elapsed 2239.72 sec LOG: finished writing run 285 to tape 51: CPU 70.81s/2128.81u sec elapsed 2246.28 sec LOG: finished writing run 286 to tape 52: CPU 70.98s/2133.91u sec elapsed 2251.58 sec LOG: performsort starting: CPU 71.50s/2149.66u sec elapsed 2268.12 sec LOG: finished writing run 287 to tape 53: CPU 71.50s/2149.71u sec elapsed 2268.17 sec LOG: finished writing final run 288 to tape 54: CPU 71.55s/2152.76u sec elapsed 2271.27 sec LOG: finished 56-way merge step: CPU 79.77s/2303.41u sec elapsed 2469.59 sec LOG: performsort done (except 233-way final merge): CPU 79.83s/2303.63u sec elapsed 2473.57 sec LOG: external sort ended, 2137818 disk blocks used: CPU 149.92s/3354.19u sec elapsed 3835.12 sec LOG: duration: 3836469.706 ms CPU 150.87s/3354.20u sec elapsed 3836.46 sec
sort_0005 3GB LOG: begin index sort: unique = f, workMem = 3145728, randomAccess = f LOG: bttext_abbrev: abbrev_distinct after 160: 1.000489 (key_distinct: 40.802210, norm_abbrev_card: 0.006253, prop_card: 0.200000) LOG: bttext_abbrev: aborted abbreviation at 160 (abbrev_distinct: 1.000489, key_distinct: 40.802210, prop_card: 0.200000) LOG: switching to external sort with 11235 tapes: CPU 6.68s/13.77u sec elapsed 22.30 sec LOG: hybrid sort-merge strategy used at row 44739242 crossover 0.750 (est 486040960.00 rows 10.86 runs) LOG: starting quicksort of run 1: CPU 6.69s/13.77u sec elapsed 22.31 sec LOG: finished quicksorting run 1: CPU 6.69s/97.10u sec elapsed 105.75 sec LOG: finished writing run 1 to tape 0: CPU 9.64s/101.87u sec elapsed 114.27 sec LOG: starting quicksort of run 2: CPU 13.07s/121.23u sec elapsed 140.43 sec LOG: finished quicksorting run 2: CPU 13.07s/238.86u sec elapsed 258.22 sec LOG: finished writing run 2 to tape 1: CPU 15.19s/243.86u sec elapsed 265.71 sec LOG: starting quicksort of run 3: CPU 17.79s/263.84u sec elapsed 289.77 sec LOG: finished quicksorting run 3: CPU 17.79s/415.77u sec elapsed 441.83 sec LOG: finished writing run 3 to tape 2: CPU 19.93s/421.60u sec elapsed 451.03 sec LOG: starting quicksort of run 4: CPU 22.27s/440.29u sec elapsed 473.12 sec LOG: finished quicksorting run 4: CPU 22.32s/607.58u sec elapsed 640.65 sec LOG: finished writing run 4 to tape 3: CPU 24.62s/614.27u sec elapsed 650.22 sec LOG: starting quicksort of run 5: CPU 27.27s/635.20u sec elapsed 676.54 sec LOG: finished quicksorting run 5: CPU 27.28s/810.63u sec elapsed 852.17 sec LOG: finished writing run 5 to tape 4: CPU 29.83s/818.29u sec elapsed 863.04 sec LOG: starting quicksort of run 6: CPU 32.56s/841.80u sec elapsed 890.26 sec LOG: finished quicksorting run 6: CPU 32.58s/1020.91u sec elapsed 1069.57 sec LOG: finished writing run 6 to tape 5: CPU 35.13s/1028.44u sec elapsed 1080.43 sec LOG: starting quicksort of run 7: CPU 38.15s/1051.68u sec elapsed 1108.19 sec LOG: finished quicksorting run 7: CPU 38.16s/1228.09u sec elapsed 1284.87 sec LOG: finished writing run 7 to tape 6: CPU 40.21s/1235.36u sec elapsed 1295.19 sec LOG: starting quicksort of run 8: CPU 42.73s/1257.59u sec elapsed 1321.09 sec LOG: finished quicksorting run 8: CPU 42.74s/1430.41u sec elapsed 1494.03 sec LOG: finished writing run 8 to tape 7: CPU 45.03s/1437.47u sec elapsed 1503.85 sec LOG: starting quicksort of run 9: CPU 47.33s/1457.52u sec elapsed 1528.74 sec LOG: finished quicksorting run 9: CPU 47.35s/1635.48u sec elapsed 1706.84 sec LOG: finished writing run 9 to tape 8: CPU 49.98s/1643.11u sec elapsed 1717.39 sec LOG: starting quicksort of run 10: CPU 52.93s/1666.17u sec elapsed 1744.01 sec LOG: finished quicksorting run 10: CPU 52.94s/1843.04u sec elapsed 1921.02 sec LOG: finished writing run 10 to tape 9: CPU 55.63s/1851.27u sec elapsed 1933.22 sec LOG: starting quicksort of run 11: CPU 58.90s/1876.96u sec elapsed 1965.21 sec LOG: finished quicksorting run 11: CPU 58.91s/2053.15u sec elapsed 2141.48 sec LOG: finished writing run 11 to tape 10: CPU 61.53s/2060.94u sec elapsed 2152.41 sec LOG: starting quicksort of run 12: CPU 64.41s/2082.92u sec elapsed 2177.76 sec LOG: finished quicksorting run 12: CPU 64.41s/2259.91u sec elapsed 2354.99 sec LOG: finished writing run 12 to tape 11: CPU 66.58s/2267.23u sec elapsed 2365.35 sec LOG: performsort starting: CPU 67.34s/2273.64u sec elapsed 2372.82 sec LOG: starting quicksort of run 13: CPU 67.34s/2273.64u sec elapsed 2372.82 sec LOG: finished quicksorting run 13: CPU 67.35s/2323.69u sec elapsed 2422.97 sec LOG: finished writing run 13 to tape 12: CPU 68.02s/2325.81u sec elapsed 2425.77 sec LOG: performsort done (except 13-way final merge): CPU 79.14s/2331.37u sec elapsed 2463.47 sec LOG: external sort ended, 2138001 disk blocks used: CPU 173.69s/2803.27u sec elapsed 3165.60 sec LOG: duration: 3168665.469 ms CPU 174.87s/2803.27u sec elapsed 3168.66 sec
origin 3GB LOG: begin index sort: unique = f, workMem = 3145728, randomAccess = f LOG: bttext_abbrev: abbrev_distinct after 160: 1.000489 (key_distinct: 40.802210, norm_abbrev_card: 0.006253, prop_card: 0.200000) LOG: bttext_abbrev: aborted abbreviation at 160 (abbrev_distinct: 1.000489, key_distinct: 40.802210, prop_card: 0.200000) LOG: switching to external sort with 11235 tapes: CPU 6.22s/12.77u sec elapsed 21.32 sec LOG: finished writing run 1 to tape 0: CPU 17.17s/460.94u sec elapsed 484.26 sec LOG: finished writing run 2 to tape 1: CPU 31.61s/1207.46u sec elapsed 1252.56 sec LOG: finished writing run 3 to tape 2: CPU 46.66s/2028.29u sec elapsed 2095.86 sec LOG: finished writing run 4 to tape 3: CPU 61.73s/2857.82u sec elapsed 2947.78 sec LOG: finished writing run 5 to tape 4: CPU 77.14s/3704.05u sec elapsed 3818.00 sec LOG: performsort starting: CPU 90.25s/4419.88u sec elapsed 4553.66 sec LOG: finished writing run 6 to tape 5: CPU 91.21s/4510.76u sec elapsed 4645.75 sec LOG: finished writing final run 7 to tape 6: CPU 93.98s/4796.14u sec elapsed 4934.17 sec LOG: performsort done (except 7-way final merge): CPU 95.75s/4810.80u sec elapsed 4951.83 sec LOG: external sort ended, 2138004 disk blocks used: CPU 186.27s/5412.53u sec elapsed 5711.58 sec LOG: duration: 5713079.171 ms CPU 187.33s/5412.54u sec elapsed 5713.07 sec
-- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
