LOG:  begin tuple sort: nkeys = 2, workMem = 65536, randomAccess = t
LOG:  switching to external sort: (ntapes=256) CPU 0.27s/0.36u sec elapsed 2.51 sec
LOG:  finished writing run 1 to tape 0: CPU 0.87s/15.48u sec elapsed 22.84 sec
LOG:  finished writing run 2 to tape 1: CPU 1.40s/25.37u sec elapsed 37.97 sec
LOG:  finished writing run 3 to tape 2: CPU 1.85s/33.86u sec elapsed 50.69 sec
LOG:  finished writing run 4 to tape 3: CPU 2.34s/41.56u sec elapsed 63.54 sec
LOG:  finished writing run 5 to tape 4: CPU 2.83s/49.14u sec elapsed 75.35 sec
LOG:  finished writing run 6 to tape 5: CPU 3.35s/56.28u sec elapsed 87.95 sec
LOG:  finished writing run 7 to tape 6: CPU 3.81s/62.99u sec elapsed 98.96 sec
LOG:  finished writing run 8 to tape 7: CPU 4.27s/70.02u sec elapsed 110.18 sec
LOG:  finished writing run 9 to tape 8: CPU 4.79s/77.75u sec elapsed 123.09 sec
LOG:  finished writing run 10 to tape 9: CPU 5.25s/84.90u sec elapsed 134.11 sec
LOG:  finished writing run 11 to tape 10: CPU 5.69s/92.15u sec elapsed 145.43 sec
LOG:  finished writing run 12 to tape 11: CPU 6.16s/98.78u sec elapsed 156.89 sec
LOG:  finished writing run 13 to tape 12: CPU 6.66s/105.80u sec elapsed 168.22 sec
LOG:  finished writing run 14 to tape 13: CPU 7.09s/112.09u sec elapsed 178.70 sec
LOG:  finished writing run 15 to tape 14: CPU 7.52s/118.75u sec elapsed 189.58 sec
LOG:  finished writing run 16 to tape 15: CPU 7.99s/125.66u sec elapsed 201.04 sec
LOG:  finished writing run 17 to tape 16: CPU 8.42s/132.20u sec elapsed 211.36 sec
LOG:  finished writing run 18 to tape 17: CPU 8.93s/138.88u sec elapsed 222.83 sec
LOG:  finished writing run 19 to tape 18: CPU 9.42s/146.30u sec elapsed 234.36 sec
LOG:  finished writing run 20 to tape 19: CPU 9.96s/154.64u sec elapsed 246.21 sec
LOG:  finished writing run 21 to tape 20: CPU 10.48s/162.00u sec elapsed 258.40 sec
LOG:  finished writing run 22 to tape 21: CPU 10.95s/168.79u sec elapsed 269.41 sec
LOG:  finished writing run 23 to tape 22: CPU 11.43s/175.66u sec elapsed 280.36 sec
LOG:  finished writing run 24 to tape 23: CPU 11.96s/183.36u sec elapsed 293.09 sec
LOG:  finished writing run 25 to tape 24: CPU 12.49s/191.35u sec elapsed 304.85 sec
LOG:  finished writing run 26 to tape 25: CPU 12.95s/197.84u sec elapsed 315.76 sec
LOG:  finished writing run 27 to tape 26: CPU 13.43s/204.41u sec elapsed 326.74 sec
LOG:  finished writing run 28 to tape 27: CPU 13.96s/210.98u sec elapsed 338.47 sec
LOG:  finished writing run 29 to tape 28: CPU 14.42s/218.45u sec elapsed 350.03 sec
LOG:  finished writing run 30 to tape 29: CPU 14.90s/225.54u sec elapsed 360.91 sec
LOG:  finished writing run 31 to tape 30: CPU 15.41s/232.16u sec elapsed 372.97 sec
LOG:  finished writing run 32 to tape 31: CPU 15.88s/239.26u sec elapsed 384.22 sec
LOG:  finished writing run 33 to tape 32: CPU 16.42s/247.06u sec elapsed 396.32 sec
LOG:  finished writing run 34 to tape 33: CPU 16.85s/253.60u sec elapsed 406.45 sec
LOG:  finished writing run 35 to tape 34: CPU 17.34s/259.90u sec elapsed 417.89 sec
LOG:  finished writing run 36 to tape 35: CPU 17.78s/266.25u sec elapsed 428.83 sec
LOG:  finished writing run 37 to tape 36: CPU 18.28s/273.26u sec elapsed 440.42 sec
LOG:  finished writing run 38 to tape 37: CPU 18.79s/280.80u sec elapsed 453.10 sec
LOG:  finished writing run 39 to tape 38: CPU 19.23s/287.43u sec elapsed 464.18 sec
LOG:  finished writing run 40 to tape 39: CPU 19.75s/294.92u sec elapsed 475.78 sec
LOG:  finished writing run 41 to tape 40: CPU 20.30s/302.87u sec elapsed 488.83 sec
LOG:  finished writing run 42 to tape 41: CPU 20.73s/309.53u sec elapsed 499.68 sec
LOG:  finished writing run 43 to tape 42: CPU 21.16s/316.33u sec elapsed 510.49 sec
LOG:  finished writing run 44 to tape 43: CPU 21.60s/322.77u sec elapsed 521.30 sec
LOG:  finished writing run 45 to tape 44: CPU 22.07s/329.97u sec elapsed 533.82 sec
LOG:  finished writing run 46 to tape 45: CPU 22.55s/336.69u sec elapsed 544.18 sec
LOG:  finished writing run 47 to tape 46: CPU 23.01s/343.78u sec elapsed 558.01 sec
LOG:  finished writing run 48 to tape 47: CPU 23.42s/350.44u sec elapsed 567.56 sec
LOG:  finished writing run 49 to tape 48: CPU 23.92s/357.25u sec elapsed 579.08 sec
LOG:  finished writing run 50 to tape 49: CPU 24.41s/364.36u sec elapsed 590.24 sec
LOG:  finished writing run 51 to tape 50: CPU 24.85s/370.99u sec elapsed 600.21 sec
LOG:  finished writing run 52 to tape 51: CPU 25.33s/377.37u sec elapsed 611.31 sec
LOG:  finished writing run 53 to tape 52: CPU 25.77s/383.96u sec elapsed 621.48 sec
LOG:  finished writing run 54 to tape 53: CPU 26.23s/390.35u sec elapsed 631.59 sec
LOG:  finished writing run 55 to tape 54: CPU 26.76s/397.31u sec elapsed 642.27 sec
LOG:  finished writing run 56 to tape 55: CPU 27.29s/404.83u sec elapsed 654.39 sec
LOG:  finished writing run 57 to tape 56: CPU 27.79s/411.35u sec elapsed 664.62 sec
LOG:  finished writing run 58 to tape 57: CPU 28.27s/418.23u sec elapsed 674.97 sec
LOG:  finished writing run 59 to tape 58: CPU 28.67s/424.23u sec elapsed 684.80 sec
LOG:  finished writing run 60 to tape 59: CPU 29.12s/430.80u sec elapsed 695.20 sec
LOG:  finished writing run 61 to tape 60: CPU 29.56s/437.47u sec elapsed 705.60 sec
LOG:  finished writing run 62 to tape 61: CPU 29.96s/443.64u sec elapsed 715.52 sec
LOG:  finished writing run 63 to tape 62: CPU 30.38s/449.62u sec elapsed 725.42 sec
LOG:  finished writing run 64 to tape 63: CPU 30.83s/455.93u sec elapsed 735.48 sec
LOG:  finished writing run 65 to tape 64: CPU 31.26s/462.09u sec elapsed 745.27 sec
LOG:  finished writing run 66 to tape 65: CPU 31.68s/468.43u sec elapsed 755.42 sec
LOG:  finished writing run 67 to tape 66: CPU 32.20s/475.39u sec elapsed 766.57 sec
LOG:  finished writing run 68 to tape 67: CPU 32.71s/482.86u sec elapsed 777.49 sec
LOG:  finished writing run 69 to tape 68: CPU 33.15s/489.36u sec elapsed 788.99 sec
LOG:  finished writing run 70 to tape 69: CPU 33.61s/495.79u sec elapsed 799.57 sec
LOG:  finished writing run 71 to tape 70: CPU 34.09s/502.30u sec elapsed 810.14 sec
LOG:  finished writing run 72 to tape 71: CPU 34.58s/509.59u sec elapsed 821.10 sec
LOG:  finished writing run 73 to tape 72: CPU 35.02s/516.10u sec elapsed 831.36 sec
LOG:  finished writing run 74 to tape 73: CPU 35.49s/522.80u sec elapsed 842.09 sec
LOG:  finished writing run 75 to tape 74: CPU 35.93s/529.39u sec elapsed 852.23 sec
LOG:  finished writing run 76 to tape 75: CPU 36.41s/535.46u sec elapsed 862.33 sec
LOG:  finished writing run 77 to tape 76: CPU 36.85s/541.99u sec elapsed 872.75 sec
LOG:  finished writing run 78 to tape 77: CPU 37.27s/548.01u sec elapsed 882.64 sec
LOG:  finished writing run 79 to tape 78: CPU 37.74s/554.47u sec elapsed 893.38 sec
LOG:  finished writing run 80 to tape 79: CPU 38.23s/561.55u sec elapsed 904.87 sec
LOG:  finished writing run 81 to tape 80: CPU 38.68s/568.80u sec elapsed 915.56 sec
LOG:  finished writing run 82 to tape 81: CPU 39.15s/575.33u sec elapsed 925.97 sec
LOG:  finished writing run 83 to tape 82: CPU 39.61s/582.02u sec elapsed 936.73 sec
LOG:  finished writing run 84 to tape 83: CPU 40.16s/589.43u sec elapsed 949.33 sec
LOG:  finished writing run 85 to tape 84: CPU 40.57s/595.42u sec elapsed 958.63 sec
LOG:  finished writing run 86 to tape 85: CPU 41.01s/601.66u sec elapsed 969.48 sec
LOG:  finished writing run 87 to tape 86: CPU 41.51s/608.30u sec elapsed 980.47 sec
LOG:  finished writing run 88 to tape 87: CPU 41.96s/614.45u sec elapsed 990.19 sec
LOG:  finished writing run 89 to tape 88: CPU 42.38s/620.42u sec elapsed 1000.37 sec
LOG:  finished writing run 90 to tape 89: CPU 42.79s/626.83u sec elapsed 1011.85 sec
LOG:  finished writing run 91 to tape 90: CPU 43.23s/633.36u sec elapsed 1022.45 sec
LOG:  finished writing run 92 to tape 91: CPU 43.65s/639.65u sec elapsed 1032.89 sec
LOG:  finished writing run 93 to tape 92: CPU 44.05s/645.64u sec elapsed 1042.95 sec
LOG:  finished writing run 94 to tape 93: CPU 44.50s/651.86u sec elapsed 1054.17 sec
LOG:  finished writing run 95 to tape 94: CPU 44.93s/658.10u sec elapsed 1064.57 sec
LOG:  finished writing run 96 to tape 95: CPU 45.35s/664.39u sec elapsed 1075.14 sec
LOG:  finished writing run 97 to tape 96: CPU 45.82s/671.33u sec elapsed 1086.25 sec
LOG:  finished writing run 98 to tape 97: CPU 46.31s/678.27u sec elapsed 1096.75 sec
LOG:  finished writing run 99 to tape 98: CPU 46.77s/684.64u sec elapsed 1107.05 sec
LOG:  finished writing run 100 to tape 99: CPU 47.20s/691.16u sec elapsed 1117.65 sec
LOG:  finished writing run 101 to tape 100: CPU 47.64s/697.60u sec elapsed 1127.96 sec
LOG:  finished writing run 102 to tape 101: CPU 48.13s/704.17u sec elapsed 1138.55 sec
LOG:  finished writing run 103 to tape 102: CPU 48.58s/710.67u sec elapsed 1150.49 sec
LOG:  finished writing run 104 to tape 103: CPU 49.07s/717.84u sec elapsed 1162.72 sec
LOG:  performsort starting: CPU 49.44s/722.60u sec elapsed 1171.61 sec
LOG:  finished writing run 105 to tape 104: CPU 49.48s/723.73u sec elapsed 1172.82 sec
LOG:  finished writing final run 106 to tape 105: CPU 49.55s/725.12u sec elapsed 1174.37 sec
LOG:  finished merge step: CPU 89.50s/2159.13u sec elapsed 4116.80 sec
LOG:  performsort done: CPU 89.50s/2159.13u sec elapsed 4116.88 sec
LOG:  external sort ended, 818272 disk blocks used: CPU 90.47s/2159.13u sec elapsed 4132.91 sec