trace_sort.log
application/octet-stream
Filename: trace_sort.log
Type: application/octet-stream
Part: 0
LOG: begin index sort: unique = f, workMem = 698709, randomAccess = f LOG: begin index sort: unique = f, workMem = 698709, randomAccess = f CONTEXT: parallel worker LOG: begin index sort: unique = f, workMem = 698709, randomAccess = f CONTEXT: parallel worker LOG: 0 switching to external sort with 501 tapes: CPU: user: 4.11 s, system: 1.95 s, elapsed: 6.27 s LOG: 0 starting quicksort of run 1: CPU: user: 4.11 s, system: 1.95 s, elapsed: 6.27 s LOG: 2 switching to external sort with 501 tapes: CPU: user: 3.88 s, system: 2.23 s, elapsed: 6.27 s CONTEXT: parallel worker LOG: 2 starting quicksort of run 1: CPU: user: 3.88 s, system: 2.23 s, elapsed: 6.27 s CONTEXT: parallel worker LOG: 1 switching to external sort with 501 tapes: CPU: user: 3.83 s, system: 2.35 s, elapsed: 6.36 s CONTEXT: parallel worker LOG: 1 starting quicksort of run 1: CPU: user: 3.83 s, system: 2.35 s, elapsed: 6.36 s CONTEXT: parallel worker LOG: 2 finished quicksort of run 1: CPU: user: 14.16 s, system: 2.23 s, elapsed: 16.55 s CONTEXT: parallel worker LOG: 0 finished quicksort of run 1: CPU: user: 14.55 s, system: 1.95 s, elapsed: 16.70 s LOG: 0 finished writing run 1 to tape 0: CPU: user: 15.45 s, system: 2.74 s, elapsed: 18.40 s LOG: 2 finished writing run 1 to tape 0: CPU: user: 15.16 s, system: 2.91 s, elapsed: 18.23 s CONTEXT: parallel worker LOG: 1 finished quicksort of run 1: CPU: user: 14.41 s, system: 2.35 s, elapsed: 16.94 s CONTEXT: parallel worker LOG: 1 finished writing run 1 to tape 0: CPU: user: 15.19 s, system: 3.26 s, elapsed: 18.87 s CONTEXT: parallel worker LOG: 2 starting quicksort of run 2: CPU: user: 19.23 s, system: 4.44 s, elapsed: 23.96 s CONTEXT: parallel worker LOG: 0 starting quicksort of run 2: CPU: user: 19.57 s, system: 4.22 s, elapsed: 24.19 s LOG: 1 starting quicksort of run 2: CPU: user: 19.03 s, system: 5.05 s, elapsed: 24.58 s CONTEXT: parallel worker LOG: 2 finished quicksort of run 2: CPU: user: 29.53 s, system: 4.44 s, elapsed: 34.25 s CONTEXT: parallel worker LOG: 0 finished quicksort of run 2: CPU: user: 30.18 s, system: 4.22 s, elapsed: 34.80 s LOG: 0 finished writing run 2 to tape 1: CPU: user: 31.01 s, system: 5.00 s, elapsed: 36.41 s LOG: 2 finished writing run 2 to tape 1: CPU: user: 30.24 s, system: 5.30 s, elapsed: 35.83 s CONTEXT: parallel worker LOG: 1 finished quicksort of run 2: CPU: user: 29.68 s, system: 5.05 s, elapsed: 35.24 s CONTEXT: parallel worker LOG: 1 finished writing run 2 to tape 1: CPU: user: 30.38 s, system: 6.00 s, elapsed: 36.89 s CONTEXT: parallel worker LOG: 2 starting quicksort of run 3: CPU: user: 33.99 s, system: 7.00 s, elapsed: 41.38 s CONTEXT: parallel worker LOG: 0 starting quicksort of run 3: CPU: user: 34.74 s, system: 6.48 s, elapsed: 41.83 s LOG: 1 starting quicksort of run 3: CPU: user: 33.96 s, system: 7.64 s, elapsed: 42.29 s CONTEXT: parallel worker LOG: 0 finished quicksort of run 3: CPU: user: 43.32 s, system: 6.48 s, elapsed: 50.41 s LOG: 0 finished writing run 3 to tape 2: CPU: user: 43.91 s, system: 7.30 s, elapsed: 51.90 s LOG: 2 finished quicksort of run 3: CPU: user: 43.44 s, system: 7.00 s, elapsed: 50.87 s CONTEXT: parallel worker LOG: 1 finished quicksort of run 3: CPU: user: 43.25 s, system: 7.64 s, elapsed: 51.58 s CONTEXT: parallel worker LOG: 2 finished writing run 3 to tape 2: CPU: user: 44.21 s, system: 7.73 s, elapsed: 52.36 s CONTEXT: parallel worker LOG: 1 finished writing run 3 to tape 2: CPU: user: 43.91 s, system: 8.48 s, elapsed: 53.49 s CONTEXT: parallel worker LOG: 0 starting quicksort of run 4: CPU: user: 47.68 s, system: 8.89 s, elapsed: 57.50 s LOG: 2 starting quicksort of run 4: CPU: user: 47.86 s, system: 9.45 s, elapsed: 57.93 s CONTEXT: parallel worker LOG: 1 starting quicksort of run 4: CPU: user: 47.68 s, system: 10.09 s, elapsed: 59.04 s CONTEXT: parallel worker LOG: 0 finished quicksort of run 4: CPU: user: 57.95 s, system: 8.89 s, elapsed: 67.76 s LOG: 0 finished writing run 4 to tape 3: CPU: user: 58.70 s, system: 9.65 s, elapsed: 69.27 s LOG: 2 finished quicksort of run 4: CPU: user: 58.18 s, system: 9.45 s, elapsed: 68.28 s CONTEXT: parallel worker LOG: 2 finished writing run 4 to tape 3: CPU: user: 58.92 s, system: 10.28 s, elapsed: 69.84 s CONTEXT: parallel worker LOG: 1 finished quicksort of run 4: CPU: user: 58.62 s, system: 10.09 s, elapsed: 69.98 s CONTEXT: parallel worker LOG: 1 finished writing run 4 to tape 3: CPU: user: 59.49 s, system: 10.76 s, elapsed: 71.52 s CONTEXT: parallel worker LOG: 0 starting quicksort of run 5: CPU: user: 62.43 s, system: 11.54 s, elapsed: 75.00 s LOG: 2 starting quicksort of run 5: CPU: user: 62.61 s, system: 12.05 s, elapsed: 75.39 s CONTEXT: parallel worker LOG: 1 starting quicksort of run 5: CPU: user: 63.00 s, system: 12.60 s, elapsed: 76.95 s CONTEXT: parallel worker LOG: 0 finished quicksort of run 5: CPU: user: 73.05 s, system: 11.55 s, elapsed: 85.62 s LOG: 0 finished writing run 5 to tape 4: CPU: user: 73.89 s, system: 12.18 s, elapsed: 87.09 s LOG: 2 finished quicksort of run 5: CPU: user: 73.39 s, system: 12.05 s, elapsed: 86.17 s CONTEXT: parallel worker LOG: 2 finished writing run 5 to tape 4: CPU: user: 74.16 s, system: 12.87 s, elapsed: 87.75 s CONTEXT: parallel worker LOG: 1 finished quicksort of run 5: CPU: user: 74.10 s, system: 12.60 s, elapsed: 88.06 s CONTEXT: parallel worker LOG: 1 finished writing run 5 to tape 4: CPU: user: 74.97 s, system: 13.22 s, elapsed: 89.85 s CONTEXT: parallel worker LOG: 0 starting quicksort of run 6: CPU: user: 77.65 s, system: 13.69 s, elapsed: 92.63 s LOG: 2 starting quicksort of run 6: CPU: user: 77.86 s, system: 14.66 s, elapsed: 93.36 s CONTEXT: parallel worker LOG: 1 starting quicksort of run 6: CPU: user: 78.43 s, system: 15.02 s, elapsed: 95.20 s CONTEXT: parallel worker LOG: 0 finished quicksort of run 6: CPU: user: 88.40 s, system: 13.71 s, elapsed: 103.39 s LOG: 0 finished writing run 6 to tape 5: CPU: user: 89.18 s, system: 14.46 s, elapsed: 104.92 s LOG: 2 finished quicksort of run 6: CPU: user: 90.32 s, system: 14.66 s, elapsed: 105.83 s CONTEXT: parallel worker LOG: 1 finished quicksort of run 6: CPU: user: 90.16 s, system: 15.02 s, elapsed: 106.93 s CONTEXT: parallel worker LOG: 2 finished writing run 6 to tape 5: CPU: user: 91.12 s, system: 15.41 s, elapsed: 107.37 s CONTEXT: parallel worker LOG: 1 finished writing run 6 to tape 5: CPU: user: 91.13 s, system: 15.84 s, elapsed: 108.73 s CONTEXT: parallel worker LOG: 0 starting quicksort of run 7: CPU: user: 93.05 s, system: 15.89 s, elapsed: 110.29 s LOG: 2 starting quicksort of run 7: CPU: user: 94.78 s, system: 17.12 s, elapsed: 112.94 s CONTEXT: parallel worker LOG: 1 starting quicksort of run 7: CPU: user: 94.59 s, system: 17.62 s, elapsed: 114.12 s CONTEXT: parallel worker LOG: 0 finished quicksort of run 7: CPU: user: 103.72 s, system: 15.89 s, elapsed: 120.96 s LOG: 0 finished writing run 7 to tape 6: CPU: user: 104.56 s, system: 16.58 s, elapsed: 122.49 s LOG: 2 finished quicksort of run 7: CPU: user: 106.14 s, system: 17.12 s, elapsed: 124.30 s CONTEXT: parallel worker LOG: 1 finished quicksort of run 7: CPU: user: 105.40 s, system: 17.62 s, elapsed: 124.94 s CONTEXT: parallel worker LOG: 2 finished writing run 7 to tape 6: CPU: user: 106.84 s, system: 18.04 s, elapsed: 125.92 s CONTEXT: parallel worker LOG: 1 finished writing run 7 to tape 6: CPU: user: 106.20 s, system: 18.45 s, elapsed: 126.62 s CONTEXT: parallel worker LOG: 0 starting quicksort of run 8: CPU: user: 108.06 s, system: 18.00 s, elapsed: 127.43 s LOG: 2 starting quicksort of run 8: CPU: user: 110.55 s, system: 19.74 s, elapsed: 131.47 s CONTEXT: parallel worker LOG: 1 starting quicksort of run 8: CPU: user: 109.84 s, system: 20.09 s, elapsed: 132.06 s CONTEXT: parallel worker LOG: 0 finished quicksort of run 8: CPU: user: 119.34 s, system: 18.00 s, elapsed: 138.71 s LOG: 0 finished writing run 8 to tape 7: CPU: user: 120.15 s, system: 18.61 s, elapsed: 140.13 s LOG: 2 finished quicksort of run 8: CPU: user: 120.51 s, system: 19.74 s, elapsed: 141.42 s CONTEXT: parallel worker LOG: 2 finished writing run 8 to tape 7: CPU: user: 121.35 s, system: 20.37 s, elapsed: 142.89 s CONTEXT: parallel worker LOG: 1 finished quicksort of run 8: CPU: user: 120.71 s, system: 20.09 s, elapsed: 142.94 s CONTEXT: parallel worker LOG: 1 finished writing run 8 to tape 7: CPU: user: 121.46 s, system: 20.82 s, elapsed: 144.42 s CONTEXT: parallel worker LOG: 0 starting quicksort of run 9: CPU: user: 123.88 s, system: 19.95 s, elapsed: 145.23 s LOG: 2 starting quicksort of run 9: CPU: user: 124.86 s, system: 22.16 s, elapsed: 148.27 s CONTEXT: parallel worker LOG: 1 starting quicksort of run 9: CPU: user: 124.98 s, system: 22.37 s, elapsed: 149.58 s CONTEXT: parallel worker LOG: 0 finished quicksort of run 9: CPU: user: 134.03 s, system: 19.95 s, elapsed: 155.39 s LOG: 0 finished writing run 9 to tape 8: CPU: user: 134.80 s, system: 20.49 s, elapsed: 156.70 s LOG: 2 finished quicksort of run 9: CPU: user: 133.94 s, system: 22.16 s, elapsed: 157.35 s CONTEXT: parallel worker LOG: 2 finished writing run 9 to tape 8: CPU: user: 134.62 s, system: 22.74 s, elapsed: 158.62 s CONTEXT: parallel worker LOG: 1 finished quicksort of run 9: CPU: user: 135.31 s, system: 22.37 s, elapsed: 159.91 s CONTEXT: parallel worker LOG: 1 finished writing run 9 to tape 8: CPU: user: 136.06 s, system: 22.91 s, elapsed: 161.21 s CONTEXT: parallel worker LOG: 0 starting quicksort of run 10: CPU: user: 138.56 s, system: 21.49 s, elapsed: 161.46 s LOG: 2 starting quicksort of run 10: CPU: user: 138.40 s, system: 23.83 s, elapsed: 163.61 s CONTEXT: parallel worker LOG: 1 starting quicksort of run 10: CPU: user: 139.77 s, system: 24.10 s, elapsed: 166.14 s CONTEXT: parallel worker LOG: 0 finished quicksort of run 10: CPU: user: 148.27 s, system: 21.49 s, elapsed: 171.17 s LOG: 0 finished writing run 10 to tape 9: CPU: user: 148.88 s, system: 22.19 s, elapsed: 172.50 s LOG: 2 finished quicksort of run 10: CPU: user: 148.37 s, system: 23.83 s, elapsed: 173.58 s CONTEXT: parallel worker LOG: 2 finished writing run 10 to tape 9: CPU: user: 149.10 s, system: 24.46 s, elapsed: 174.93 s CONTEXT: parallel worker LOG: 1 finished quicksort of run 10: CPU: user: 150.40 s, system: 24.10 s, elapsed: 176.76 s CONTEXT: parallel worker LOG: 0 starting quicksort of run 11: CPU: user: 152.61 s, system: 23.52 s, elapsed: 177.59 s LOG: 1 finished writing run 10 to tape 9: CPU: user: 151.10 s, system: 24.91 s, elapsed: 178.27 s CONTEXT: parallel worker LOG: 2 starting quicksort of run 11: CPU: user: 152.74 s, system: 26.09 s, elapsed: 180.27 s CONTEXT: parallel worker LOG: 1 starting quicksort of run 11: CPU: user: 154.87 s, system: 26.05 s, elapsed: 183.23 s CONTEXT: parallel worker LOG: 0 finished quicksort of run 11: CPU: user: 162.47 s, system: 23.52 s, elapsed: 187.46 s LOG: 0 finished writing run 11 to tape 10: CPU: user: 163.16 s, system: 24.19 s, elapsed: 188.82 s LOG: 2 finished quicksort of run 11: CPU: user: 162.03 s, system: 26.09 s, elapsed: 189.57 s CONTEXT: parallel worker LOG: 2 finished writing run 11 to tape 10: CPU: user: 162.80 s, system: 26.70 s, elapsed: 190.94 s CONTEXT: parallel worker LOG: 0 starting quicksort of run 12: CPU: user: 166.70 s, system: 25.66 s, elapsed: 193.86 s LOG: 1 finished quicksort of run 11: CPU: user: 165.79 s, system: 26.05 s, elapsed: 194.15 s CONTEXT: parallel worker LOG: 1 finished writing run 11 to tape 10: CPU: user: 166.51 s, system: 26.76 s, elapsed: 195.59 s CONTEXT: parallel worker LOG: 2 starting quicksort of run 12: CPU: user: 166.49 s, system: 28.12 s, elapsed: 196.12 s CONTEXT: parallel worker LOG: 1 starting quicksort of run 12: CPU: user: 169.91 s, system: 27.95 s, elapsed: 200.21 s CONTEXT: parallel worker LOG: 0 finished quicksort of run 12: CPU: user: 177.26 s, system: 25.66 s, elapsed: 204.42 s LOG: 0 finished writing run 12 to tape 11: CPU: user: 178.16 s, system: 26.14 s, elapsed: 205.81 s LOG: 2 finished quicksort of run 12: CPU: user: 176.79 s, system: 28.12 s, elapsed: 206.41 s CONTEXT: parallel worker LOG: 2 finished writing run 12 to tape 11: CPU: user: 177.49 s, system: 28.82 s, elapsed: 207.82 s CONTEXT: parallel worker LOG: 0 starting quicksort of run 13: CPU: user: 181.64 s, system: 27.54 s, elapsed: 210.75 s LOG: 1 finished quicksort of run 12: CPU: user: 180.69 s, system: 27.95 s, elapsed: 210.99 s CONTEXT: parallel worker LOG: 1 finished writing run 12 to tape 11: CPU: user: 181.49 s, system: 28.54 s, elapsed: 212.37 s CONTEXT: parallel worker LOG: 2 starting quicksort of run 13: CPU: user: 180.99 s, system: 30.52 s, elapsed: 213.03 s CONTEXT: parallel worker LOG: 1 starting quicksort of run 13: CPU: user: 184.84 s, system: 29.84 s, elapsed: 217.04 s CONTEXT: parallel worker LOG: 0 finished quicksort of run 13: CPU: user: 192.36 s, system: 27.56 s, elapsed: 221.47 s LOG: 0 finished writing run 13 to tape 12: CPU: user: 193.14 s, system: 28.17 s, elapsed: 222.86 s LOG: 2 finished quicksort of run 13: CPU: user: 192.09 s, system: 30.52 s, elapsed: 224.14 s CONTEXT: parallel worker LOG: 2 finished writing run 13 to tape 12: CPU: user: 193.02 s, system: 31.05 s, elapsed: 225.59 s CONTEXT: parallel worker LOG: 0 starting quicksort of run 14: CPU: user: 196.81 s, system: 29.32 s, elapsed: 227.71 s LOG: 1 finished quicksort of run 13: CPU: user: 196.63 s, system: 29.85 s, elapsed: 228.85 s CONTEXT: parallel worker LOG: 1 finished writing run 13 to tape 12: CPU: user: 197.46 s, system: 30.52 s, elapsed: 230.35 s CONTEXT: parallel worker LOG: 2 starting quicksort of run 14: CPU: user: 196.81 s, system: 32.22 s, elapsed: 230.55 s CONTEXT: parallel worker LOG: 1 starting quicksort of run 14: CPU: user: 200.97 s, system: 31.46 s, elapsed: 234.79 s CONTEXT: parallel worker LOG: 0 finished quicksort of run 14: CPU: user: 207.41 s, system: 29.32 s, elapsed: 238.32 s LOG: 0 finished writing run 14 to tape 13: CPU: user: 208.12 s, system: 30.03 s, elapsed: 239.72 s LOG: 2 finished quicksort of run 14: CPU: user: 206.71 s, system: 32.22 s, elapsed: 240.45 s CONTEXT: parallel worker LOG: 2 finished writing run 14 to tape 13: CPU: user: 207.48 s, system: 32.90 s, elapsed: 241.89 s CONTEXT: parallel worker LOG: performsort of 0 starting: CPU: user: 211.59 s, system: 31.30 s, elapsed: 244.54 s LOG: 0 starting quicksort of run 15: CPU: user: 211.59 s, system: 31.30 s, elapsed: 244.56 s LOG: performsort of 2 starting: CPU: user: 209.33 s, system: 33.58 s, elapsed: 244.49 s CONTEXT: parallel worker LOG: 2 starting quicksort of run 15: CPU: user: 209.33 s, system: 33.60 s, elapsed: 244.51 s CONTEXT: parallel worker LOG: 1 finished quicksort of run 14: CPU: user: 210.81 s, system: 31.46 s, elapsed: 244.63 s CONTEXT: parallel worker LOG: 1 finished writing run 14 to tape 13: CPU: user: 211.44 s, system: 32.15 s, elapsed: 245.95 s CONTEXT: parallel worker LOG: performsort of 1 starting: CPU: user: 211.44 s, system: 32.15 s, elapsed: 245.95 s CONTEXT: parallel worker LOG: 1 starting quicksort of run 15: CPU: user: 211.44 s, system: 32.15 s, elapsed: 245.95 s CONTEXT: parallel worker LOG: 1 finished quicksort of run 15: CPU: user: 211.44 s, system: 32.15 s, elapsed: 245.95 s CONTEXT: parallel worker LOG: 1 finished writing run 15 to tape 14: CPU: user: 211.44 s, system: 32.15 s, elapsed: 245.95 s CONTEXT: parallel worker LOG: 1 using 698564 KB of memory for read buffers among 15 input tapes CONTEXT: parallel worker LOG: 2 finished quicksort of run 15: CPU: user: 214.26 s, system: 33.60 s, elapsed: 249.44 s CONTEXT: parallel worker LOG: 2 finished writing run 15 to tape 14: CPU: user: 214.65 s, system: 33.91 s, elapsed: 250.14 s CONTEXT: parallel worker LOG: 2 using 698564 KB of memory for read buffers among 15 input tapes CONTEXT: parallel worker LOG: 0 finished quicksort of run 15: CPU: user: 222.02 s, system: 31.30 s, elapsed: 254.98 s LOG: 0 finished writing run 15 to tape 14: CPU: user: 222.72 s, system: 31.99 s, elapsed: 256.37 s LOG: 0 using 698564 KB of memory for read buffers among 15 input tapes LOG: 1 finished 15-way merge step: CPU: user: 236.79 s, system: 42.82 s, elapsed: 281.97 s CONTEXT: parallel worker LOG: performsort of 1 done: CPU: user: 236.79 s, system: 42.93 s, elapsed: 282.07 s CONTEXT: parallel worker LOG: parallel external sort of 1 ended, 433054 disk blocks used: CPU: user: 236.79 s, system: 42.93 s, elapsed: 283.78 s CONTEXT: parallel worker LOG: 2 finished 15-way merge step: CPU: user: 241.38 s, system: 44.55 s, elapsed: 287.52 s CONTEXT: parallel worker LOG: performsort of 2 done: CPU: user: 241.38 s, system: 44.69 s, elapsed: 287.66 s CONTEXT: parallel worker LOG: parallel external sort of 2 ended, 448565 disk blocks used: CPU: user: 241.38 s, system: 44.69 s, elapsed: 290.58 s CONTEXT: parallel worker LOG: 0 finished 15-way merge step: CPU: user: 250.03 s, system: 42.52 s, elapsed: 294.21 s LOG: performsort of 0 done: CPU: user: 250.03 s, system: 42.66 s, elapsed: 294.35 s LOG: parallel external sort of 0 ended, 462886 disk blocks used: CPU: user: 250.03 s, system: 42.66 s, elapsed: 298.95 s LOG: begin index sort: unique = f, workMem = 2096128, randomAccess = f LOG: performsort of -1 starting: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s LOG: could not rmdir directory "base/pgsql_tmp/pgsql_tmp5088.0.sharedfileset": Directory not empty ERROR: could not determine size of temporary file "0" ********** Error ********** ERROR: could not determine size of temporary file "0" SQL state: 58P01