LOG:  begin tuple sort: nkeys = 2, workMem = 65536, randomAccess = t
LOG:  switching to external sort: CPU 0.25s/0.39u sec elapsed 1.18 sec
LOG:  finished writing run 1: CPU 0.79s/15.29u sec elapsed 19.75 sec
LOG:  finished writing run 2: CPU 1.29s/25.13u sec elapsed 33.81 sec
LOG:  finished writing run 3: CPU 1.75s/33.26u sec elapsed 45.11 sec
LOG:  finished writing run 4: CPU 2.42s/41.00u sec elapsed 58.49 sec
LOG:  finished writing run 5: CPU 3.04s/48.57u sec elapsed 70.06 sec
LOG:  finished writing run 6: CPU 3.67s/55.95u sec elapsed 81.97 sec
LOG:  finished writing run 7: CPU 4.31s/63.22u sec elapsed 94.80 sec
LOG:  finished writing run 8: CPU 4.89s/70.54u sec elapsed 106.45 sec
LOG:  finished writing run 9: CPU 5.55s/77.76u sec elapsed 119.85 sec
LOG:  finished writing run 10: CPU 6.19s/85.27u sec elapsed 132.30 sec
LOG:  finished writing run 11: CPU 6.81s/92.68u sec elapsed 145.78 sec
LOG:  finished writing run 12: CPU 7.47s/99.63u sec elapsed 159.01 sec
LOG:  finished writing run 13: CPU 8.11s/106.92u sec elapsed 170.88 sec
LOG:  finished writing run 14: CPU 8.76s/113.67u sec elapsed 184.52 sec
LOG:  finished writing run 15: CPU 9.39s/120.32u sec elapsed 196.05 sec
LOG:  finished writing run 16: CPU 10.04s/127.61u sec elapsed 211.77 sec
LOG:  finished writing run 17: CPU 10.67s/134.80u sec elapsed 224.49 sec
LOG:  finished writing run 18: CPU 11.27s/141.30u sec elapsed 234.93 sec
LOG:  finished writing run 19: CPU 11.82s/147.79u sec elapsed 245.44 sec
LOG:  finished writing run 20: CPU 12.40s/154.45u sec elapsed 256.55 sec
LOG:  finished writing run 21: CPU 13.05s/160.99u sec elapsed 268.55 sec
LOG:  finished writing run 22: CPU 13.69s/168.26u sec elapsed 280.16 sec
LOG:  finished writing run 23: CPU 14.29s/175.05u sec elapsed 291.57 sec
LOG:  finished writing run 24: CPU 14.95s/182.21u sec elapsed 304.59 sec
LOG:  finished writing run 25: CPU 15.52s/188.82u sec elapsed 315.75 sec
LOG:  finished writing run 26: CPU 16.23s/196.91u sec elapsed 329.30 sec
LOG:  finished writing run 27: CPU 16.82s/203.89u sec elapsed 340.90 sec
LOG:  finished writing run 28: CPU 17.48s/210.93u sec elapsed 354.44 sec
LOG:  finished writing run 29: CPU 18.07s/217.16u sec elapsed 365.60 sec
LOG:  finished writing run 30: CPU 18.69s/223.92u sec elapsed 377.15 sec
LOG:  finished writing run 31: CPU 19.39s/231.10u sec elapsed 391.09 sec
LOG:  finished writing run 32: CPU 20.03s/237.83u sec elapsed 404.30 sec
LOG:  finished writing run 33: CPU 20.67s/245.04u sec elapsed 417.78 sec
LOG:  finished writing run 34: CPU 21.35s/253.22u sec elapsed 431.70 sec
LOG:  finished writing run 35: CPU 22.02s/259.88u sec elapsed 444.64 sec
LOG:  finished writing run 36: CPU 22.63s/266.52u sec elapsed 455.38 sec
LOG:  finished writing run 37: CPU 23.21s/273.07u sec elapsed 466.02 sec
LOG:  finished writing run 38: CPU 23.85s/280.20u sec elapsed 477.81 sec
LOG:  finished writing run 39: CPU 24.47s/286.92u sec elapsed 490.00 sec
LOG:  finished writing run 40: CPU 25.13s/294.33u sec elapsed 502.36 sec
LOG:  finished writing run 41: CPU 25.79s/301.49u sec elapsed 515.60 sec
LOG:  finished writing run 42: CPU 26.42s/308.47u sec elapsed 527.15 sec
LOG:  finished writing run 43: CPU 27.07s/315.10u sec elapsed 540.04 sec
LOG:  finished writing run 44: CPU 27.65s/321.53u sec elapsed 551.21 sec
LOG:  finished writing run 45: CPU 28.24s/328.55u sec elapsed 562.53 sec
LOG:  finished writing run 46: CPU 28.97s/336.26u sec elapsed 576.52 sec
LOG:  finished writing run 47: CPU 29.55s/342.87u sec elapsed 587.49 sec
LOG:  finished writing run 48: CPU 30.19s/349.29u sec elapsed 600.15 sec
LOG:  finished writing run 49: CPU 30.77s/356.16u sec elapsed 611.30 sec
LOG:  finished writing run 50: CPU 31.37s/362.60u sec elapsed 623.15 sec
LOG:  finished writing run 51: CPU 31.99s/369.28u sec elapsed 635.14 sec
LOG:  finished writing run 52: CPU 32.59s/376.67u sec elapsed 647.61 sec
LOG:  finished writing run 53: CPU 33.21s/383.23u sec elapsed 659.79 sec
LOG:  finished writing run 54: CPU 33.81s/389.43u sec elapsed 669.98 sec
LOG:  finished writing run 55: CPU 34.40s/396.33u sec elapsed 681.33 sec
LOG:  finished writing run 56: CPU 34.97s/403.27u sec elapsed 692.09 sec
LOG:  finished writing run 57: CPU 35.55s/409.43u sec elapsed 702.82 sec
LOG:  finished writing run 58: CPU 36.12s/415.79u sec elapsed 714.68 sec
LOG:  finished writing run 59: CPU 36.72s/422.38u sec elapsed 725.80 sec
LOG:  finished writing run 60: CPU 37.30s/429.51u sec elapsed 737.33 sec
LOG:  finished writing run 61: CPU 37.93s/435.85u sec elapsed 749.49 sec
LOG:  finished writing run 62: CPU 38.71s/444.21u sec elapsed 765.26 sec
LOG:  finished writing run 63: CPU 39.26s/450.65u sec elapsed 776.38 sec
LOG:  finished writing run 64: CPU 39.84s/457.17u sec elapsed 787.53 sec
LOG:  finished writing run 65: CPU 40.47s/463.53u sec elapsed 800.61 sec
LOG:  finished writing run 66: CPU 41.01s/470.02u sec elapsed 812.05 sec
LOG:  finished writing run 67: CPU 41.72s/476.66u sec elapsed 825.01 sec
LOG:  finished writing run 68: CPU 42.38s/484.39u sec elapsed 837.59 sec
LOG:  finished writing run 69: CPU 43.04s/490.90u sec elapsed 850.66 sec
LOG:  finished writing run 70: CPU 43.65s/497.70u sec elapsed 862.45 sec
LOG:  finished writing run 71: CPU 44.31s/504.37u sec elapsed 874.99 sec
LOG:  finished writing run 72: CPU 44.89s/510.81u sec elapsed 886.81 sec
LOG:  finished writing run 73: CPU 45.44s/517.28u sec elapsed 898.07 sec
LOG:  finished writing run 74: CPU 46.10s/524.10u sec elapsed 911.08 sec
LOG:  finished writing run 75: CPU 46.65s/530.52u sec elapsed 922.09 sec
LOG:  finished writing run 76: CPU 47.26s/537.12u sec elapsed 935.34 sec
LOG:  finished writing run 77: CPU 47.83s/543.77u sec elapsed 946.49 sec
LOG:  finished writing run 78: CPU 48.48s/550.73u sec elapsed 958.10 sec
LOG:  finished writing run 79: CPU 49.14s/557.54u sec elapsed 970.90 sec
LOG:  finished writing run 80: CPU 49.77s/564.60u sec elapsed 982.79 sec
LOG:  finished writing run 81: CPU 50.42s/571.48u sec elapsed 995.26 sec
LOG:  finished writing run 82: CPU 51.04s/578.56u sec elapsed 1006.57 sec
LOG:  finished writing run 83: CPU 51.64s/585.34u sec elapsed 1017.57 sec
LOG:  finished writing run 84: CPU 52.23s/591.96u sec elapsed 1029.00 sec
LOG:  finished writing run 85: CPU 52.84s/598.50u sec elapsed 1041.13 sec
LOG:  finished writing run 86: CPU 53.45s/605.38u sec elapsed 1052.22 sec
LOG:  finished writing run 87: CPU 54.11s/612.66u sec elapsed 1064.52 sec
LOG:  finished writing run 88: CPU 54.73s/620.00u sec elapsed 1076.61 sec
LOG:  finished writing run 89: CPU 55.33s/626.51u sec elapsed 1087.48 sec
LOG:  finished writing run 90: CPU 55.92s/632.85u sec elapsed 1098.38 sec
LOG:  finished writing run 91: CPU 56.48s/638.97u sec elapsed 1109.10 sec
LOG:  finished writing run 92: CPU 57.10s/645.54u sec elapsed 1121.25 sec
LOG:  finished writing run 93: CPU 57.69s/651.96u sec elapsed 1132.15 sec
LOG:  finished writing run 94: CPU 58.30s/658.61u sec elapsed 1143.81 sec
LOG:  finished writing run 95: CPU 58.91s/665.23u sec elapsed 1156.37 sec
LOG:  finished writing run 96: CPU 59.47s/671.91u sec elapsed 1167.75 sec
LOG:  finished writing run 97: CPU 60.18s/679.10u sec elapsed 1181.43 sec
LOG:  finished writing run 98: CPU 60.72s/685.90u sec elapsed 1193.10 sec
LOG:  finished writing run 99: CPU 61.32s/692.32u sec elapsed 1205.26 sec
LOG:  finished writing run 100: CPU 61.99s/700.06u sec elapsed 1218.48 sec
LOG:  finished writing run 101: CPU 62.55s/706.45u sec elapsed 1231.28 sec
LOG:  finished writing run 102: CPU 63.20s/714.00u sec elapsed 1243.58 sec
LOG:  finished writing run 103: CPU 63.83s/720.38u sec elapsed 1256.51 sec
LOG:  finished writing run 104: CPU 64.39s/727.04u sec elapsed 1267.64 sec
LOG:  performsort starting: CPU 64.83s/732.23u sec elapsed 1277.40 sec
LOG:  finished writing run 105: CPU 64.90s/733.34u sec elapsed 1278.85 sec
LOG:  finished writing final run 106: CPU 64.98s/734.78u sec elapsed 1280.42 sec
LOG:  finished merge step: CPU 65.20s/736.00u sec elapsed 1287.24 sec
LOG:  finished merge step: CPU 66.72s/763.05u sec elapsed 1338.02 sec
LOG:  finished merge step: CPU 68.56s/798.53u sec elapsed 1407.28 sec
LOG:  finished merge step: CPU 70.68s/830.08u sec elapsed 1471.06 sec
LOG:  finished merge step: CPU 72.78s/858.63u sec elapsed 1530.78 sec
LOG:  finished merge step: CPU 74.91s/886.03u sec elapsed 1595.45 sec
LOG:  finished merge step: CPU 77.16s/909.13u sec elapsed 1647.66 sec
LOG:  finished merge step: CPU 79.32s/933.85u sec elapsed 1704.74 sec
LOG:  finished merge step: CPU 81.15s/952.54u sec elapsed 1755.45 sec
LOG:  finished merge step: CPU 83.17s/972.56u sec elapsed 1803.80 sec
LOG:  finished merge step: CPU 85.23s/992.00u sec elapsed 1856.65 sec
LOG:  finished merge step: CPU 87.23s/1010.60u sec elapsed 1899.01 sec
LOG:  finished merge step: CPU 89.29s/1028.82u sec elapsed 1942.89 sec
LOG:  finished merge step: CPU 91.30s/1047.05u sec elapsed 1988.01 sec
LOG:  finished merge step: CPU 93.30s/1066.22u sec elapsed 2032.50 sec
LOG:  finished merge step: CPU 95.28s/1082.87u sec elapsed 2073.21 sec
LOG:  finished merge step: CPU 99.51s/1130.74u sec elapsed 2180.97 sec
LOG:  finished merge step: CPU 105.29s/1195.15u sec elapsed 2315.62 sec
LOG:  finished merge step: CPU 111.77s/1265.04u sec elapsed 2469.50 sec
LOG:  finished merge step: CPU 118.17s/1338.26u sec elapsed 2623.61 sec
LOG:  finished merge step: CPU 127.93s/1494.36u sec elapsed 3020.38 sec
LOG:  finished merge step: CPU 139.25s/1661.30u sec elapsed 3365.08 sec
LOG:  finished merge step: CPU 159.41s/2078.13u sec elapsed 4091.09 sec
LOG:  finished merge step: CPU 195.87s/3022.95u sec elapsed 5675.71 sec
LOG:  performsort done: CPU 195.87s/3022.95u sec elapsed 5675.96 sec
LOG:  external sort ended, 818272 disk blocks used: CPU 196.86s/3022.95u sec elapsed 5693.14 sec