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