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