2017-09-19 10:33:38.717 BST [71228] LOG: listening on IPv6 address "::1", port 5432 2017-09-19 10:33:38.717 BST [71228] LOG: listening on IPv4 address "127.0.0.1", port 5432 2017-09-19 10:33:38.756 BST [71228] LOG: listening on Unix socket "/tmp/.s.PGSQL.5432" 2017-09-19 10:33:38.778 BST [71229] LOG: database system was shut down at 2017-09-19 10:32:41 BST 2017-09-19 10:33:38.791 BST [71228] LOG: database system is ready to accept connections 2017-09-19 10:33:58.298 BST [71237] LOG: Worker for create index 8 2017-09-19 10:33:58.298 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:33:58.299 BST [71237] LOG: begin index sort: unique = f, workMem = 8388608, randomAccess = f 2017-09-19 10:33:58.299 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:34:18.259 BST [71244] LOG: starting quicksort of run 7/1: CPU: user: 19.35 s, system: 0.58 s, elapsed: 19.95 s 2017-09-19 10:34:18.441 BST [71243] LOG: starting quicksort of run 5/1: CPU: user: 19.57 s, system: 0.55 s, elapsed: 20.13 s 2017-09-19 10:34:18.878 BST [71242] LOG: starting quicksort of run 6/1: CPU: user: 19.84 s, system: 0.71 s, elapsed: 20.57 s 2017-09-19 10:34:18.977 BST [71240] LOG: starting quicksort of run 3/1: CPU: user: 20.05 s, system: 0.60 s, elapsed: 20.67 s 2017-09-19 10:34:19.544 BST [71239] LOG: starting quicksort of run 2/1: CPU: user: 20.62 s, system: 0.60 s, elapsed: 21.23 s 2017-09-19 10:34:19.608 BST [71241] LOG: starting quicksort of run 4/1: CPU: user: 20.74 s, system: 0.54 s, elapsed: 21.30 s 2017-09-19 10:34:19.710 BST [71238] LOG: starting quicksort of run 1/1: CPU: user: 20.88 s, system: 0.51 s, elapsed: 21.40 s 2017-09-19 10:34:19.857 BST [71237] LOG: starting quicksort of run 0/1: CPU: user: 21.08 s, system: 0.46 s, elapsed: 21.55 s 2017-09-19 10:34:19.857 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:34:34.111 BST [71244] LOG: finished quicksort of run 7/1: CPU: user: 34.91 s, system: 0.87 s, elapsed: 35.80 s 2017-09-19 10:34:35.180 BST [71240] LOG: finished quicksort of run 3/1: CPU: user: 36.04 s, system: 0.81 s, elapsed: 36.87 s 2017-09-19 10:34:35.242 BST [71242] LOG: finished quicksort of run 6/1: CPU: user: 35.88 s, system: 1.03 s, elapsed: 36.93 s 2017-09-19 10:34:35.363 BST [71238] LOG: finished quicksort of run 1/1: CPU: user: 36.43 s, system: 0.58 s, elapsed: 37.05 s 2017-09-19 10:34:35.434 BST [71241] LOG: finished quicksort of run 4/1: CPU: user: 36.26 s, system: 0.85 s, elapsed: 37.12 s 2017-09-19 10:34:35.471 BST [71243] LOG: finished quicksort of run 5/1: CPU: user: 36.24 s, system: 0.91 s, elapsed: 37.16 s 2017-09-19 10:34:35.814 BST [71239] LOG: finished quicksort of run 2/1: CPU: user: 36.67 s, system: 0.82 s, elapsed: 37.50 s 2017-09-19 10:34:38.979 BST [71237] LOG: finished quicksort of run 0/1: CPU: user: 39.98 s, system: 0.69 s, elapsed: 40.68 s 2017-09-19 10:34:38.979 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:34:40.902 BST [71244] LOG: finished writing run 7/1 to tape 0: CPU: user: 41.30 s, system: 1.27 s, elapsed: 42.59 s 2017-09-19 10:34:41.379 BST [71243] LOG: finished writing run 5/1 to tape 0: CPU: user: 41.90 s, system: 1.16 s, elapsed: 43.07 s 2017-09-19 10:34:41.424 BST [71242] LOG: finished writing run 6/1 to tape 0: CPU: user: 41.72 s, system: 1.37 s, elapsed: 43.11 s 2017-09-19 10:34:41.671 BST [71241] LOG: finished writing run 4/1 to tape 0: CPU: user: 42.09 s, system: 1.25 s, elapsed: 43.36 s 2017-09-19 10:34:41.725 BST [71238] LOG: finished writing run 1/1 to tape 0: CPU: user: 42.51 s, system: 0.86 s, elapsed: 43.42 s 2017-09-19 10:34:42.073 BST [71240] LOG: finished writing run 3/1 to tape 0: CPU: user: 42.58 s, system: 1.17 s, elapsed: 43.76 s 2017-09-19 10:34:43.748 BST [71239] LOG: finished writing run 2/1 to tape 0: CPU: user: 44.11 s, system: 1.29 s, elapsed: 45.44 s 2017-09-19 10:34:46.426 BST [71237] LOG: finished writing run 0/1 to tape 0: CPU: user: 47.06 s, system: 1.02 s, elapsed: 48.12 s 2017-09-19 10:34:46.426 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:34:58.682 BST [71243] LOG: starting quicksort of run 5/2: CPU: user: 58.82 s, system: 1.54 s, elapsed: 60.37 s 2017-09-19 10:34:58.820 BST [71244] LOG: starting quicksort of run 7/2: CPU: user: 58.67 s, system: 1.83 s, elapsed: 60.51 s 2017-09-19 10:34:59.199 BST [71238] LOG: starting quicksort of run 1/2: CPU: user: 59.51 s, system: 1.33 s, elapsed: 60.89 s 2017-09-19 10:34:59.530 BST [71242] LOG: starting quicksort of run 6/2: CPU: user: 59.34 s, system: 1.84 s, elapsed: 61.22 s 2017-09-19 10:34:59.962 BST [71240] LOG: starting quicksort of run 3/2: CPU: user: 60.00 s, system: 1.63 s, elapsed: 61.65 s 2017-09-19 10:35:00.389 BST [71241] LOG: starting quicksort of run 4/2: CPU: user: 60.29 s, system: 1.77 s, elapsed: 62.08 s 2017-09-19 10:35:02.193 BST [71239] LOG: starting quicksort of run 2/2: CPU: user: 62.09 s, system: 1.75 s, elapsed: 63.88 s 2017-09-19 10:35:06.429 BST [71237] LOG: starting quicksort of run 0/2: CPU: user: 66.48 s, system: 1.56 s, elapsed: 68.13 s 2017-09-19 10:35:06.429 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:35:14.430 BST [71243] LOG: finished quicksort of run 5/2: CPU: user: 74.42 s, system: 1.67 s, elapsed: 76.12 s 2017-09-19 10:35:15.350 BST [71244] LOG: finished quicksort of run 7/2: CPU: user: 75.00 s, system: 2.02 s, elapsed: 77.04 s 2017-09-19 10:35:15.424 BST [71238] LOG: finished quicksort of run 1/2: CPU: user: 75.66 s, system: 1.40 s, elapsed: 77.11 s 2017-09-19 10:35:17.650 BST [71242] LOG: finished quicksort of run 6/2: CPU: user: 77.20 s, system: 2.10 s, elapsed: 79.34 s 2017-09-19 10:35:18.419 BST [71240] LOG: finished quicksort of run 3/2: CPU: user: 78.19 s, system: 1.90 s, elapsed: 80.11 s 2017-09-19 10:35:18.554 BST [71239] LOG: finished quicksort of run 2/2: CPU: user: 78.25 s, system: 1.95 s, elapsed: 80.24 s 2017-09-19 10:35:18.800 BST [71241] LOG: finished quicksort of run 4/2: CPU: user: 78.36 s, system: 2.11 s, elapsed: 80.49 s 2017-09-19 10:35:21.401 BST [71238] LOG: finished writing run 1/2 to tape 1: CPU: user: 81.49 s, system: 1.55 s, elapsed: 83.09 s 2017-09-19 10:35:21.587 BST [71244] LOG: finished writing run 7/2 to tape 1: CPU: user: 80.92 s, system: 2.34 s, elapsed: 83.27 s 2017-09-19 10:35:21.776 BST [71243] LOG: finished writing run 5/2 to tape 1: CPU: user: 81.24 s, system: 2.19 s, elapsed: 83.46 s 2017-09-19 10:35:24.750 BST [71239] LOG: finished writing run 2/2 to tape 1: CPU: user: 84.20 s, system: 2.20 s, elapsed: 86.44 s 2017-09-19 10:35:24.834 BST [71242] LOG: finished writing run 6/2 to tape 1: CPU: user: 84.10 s, system: 2.39 s, elapsed: 86.52 s 2017-09-19 10:35:25.029 BST [71240] LOG: finished writing run 3/2 to tape 1: CPU: user: 84.53 s, system: 2.16 s, elapsed: 86.72 s 2017-09-19 10:35:25.613 BST [71237] LOG: finished quicksort of run 0/2: CPU: user: 85.47 s, system: 1.75 s, elapsed: 87.31 s 2017-09-19 10:35:25.613 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:35:25.904 BST [71241] LOG: finished writing run 4/2 to tape 1: CPU: user: 85.14 s, system: 2.44 s, elapsed: 87.59 s 2017-09-19 10:35:33.900 BST [71237] LOG: finished writing run 0/2 to tape 1: CPU: user: 93.46 s, system: 2.05 s, elapsed: 95.60 s 2017-09-19 10:35:33.900 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:35:38.083 BST [71244] LOG: starting quicksort of run 7/3: CPU: user: 96.95 s, system: 2.77 s, elapsed: 99.77 s 2017-09-19 10:35:38.839 BST [71243] LOG: starting quicksort of run 5/3: CPU: user: 97.82 s, system: 2.67 s, elapsed: 100.53 s 2017-09-19 10:35:39.627 BST [71238] LOG: starting quicksort of run 1/3: CPU: user: 99.28 s, system: 1.98 s, elapsed: 101.32 s 2017-09-19 10:35:42.666 BST [71242] LOG: starting quicksort of run 6/3: CPU: user: 101.54 s, system: 2.78 s, elapsed: 104.35 s 2017-09-19 10:35:43.128 BST [71239] LOG: starting quicksort of run 2/3: CPU: user: 102.17 s, system: 2.60 s, elapsed: 104.82 s 2017-09-19 10:35:43.167 BST [71240] LOG: starting quicksort of run 3/3: CPU: user: 102.19 s, system: 2.63 s, elapsed: 104.86 s 2017-09-19 10:35:44.451 BST [71241] LOG: starting quicksort of run 4/3: CPU: user: 103.19 s, system: 2.93 s, elapsed: 106.14 s 2017-09-19 10:35:54.096 BST [71237] LOG: starting quicksort of run 0/3: CPU: user: 113.09 s, system: 2.62 s, elapsed: 115.79 s 2017-09-19 10:35:54.096 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:35:54.177 BST [71244] LOG: finished quicksort of run 7/3: CPU: user: 112.87 s, system: 2.93 s, elapsed: 115.86 s 2017-09-19 10:35:56.254 BST [71243] LOG: finished quicksort of run 5/3: CPU: user: 115.05 s, system: 2.83 s, elapsed: 117.94 s 2017-09-19 10:35:58.661 BST [71238] LOG: finished quicksort of run 1/3: CPU: user: 118.25 s, system: 2.05 s, elapsed: 120.35 s 2017-09-19 10:35:59.892 BST [71244] LOG: finished writing run 7/3 to tape 2: CPU: user: 118.37 s, system: 3.15 s, elapsed: 121.58 s 2017-09-19 10:36:00.049 BST [71242] LOG: finished quicksort of run 6/3: CPU: user: 118.81 s, system: 2.87 s, elapsed: 121.74 s 2017-09-19 10:36:00.435 BST [71240] LOG: finished quicksort of run 3/3: CPU: user: 119.36 s, system: 2.73 s, elapsed: 122.12 s 2017-09-19 10:36:03.355 BST [71241] LOG: finished quicksort of run 4/3: CPU: user: 122.04 s, system: 2.98 s, elapsed: 125.05 s 2017-09-19 10:36:03.504 BST [71239] LOG: finished quicksort of run 2/3: CPU: user: 122.44 s, system: 2.71 s, elapsed: 125.19 s 2017-09-19 10:36:04.510 BST [71243] LOG: finished writing run 5/3 to tape 2: CPU: user: 122.94 s, system: 3.19 s, elapsed: 126.20 s 2017-09-19 10:36:05.461 BST [71238] LOG: finished writing run 1/3 to tape 2: CPU: user: 124.77 s, system: 2.32 s, elapsed: 127.15 s 2017-09-19 10:36:07.085 BST [71240] LOG: finished writing run 3/3 to tape 2: CPU: user: 125.72 s, system: 3.03 s, elapsed: 128.77 s 2017-09-19 10:36:08.413 BST [71242] LOG: finished writing run 6/3 to tape 2: CPU: user: 126.52 s, system: 3.51 s, elapsed: 130.10 s 2017-09-19 10:36:09.525 BST [71239] LOG: finished writing run 2/3 to tape 2: CPU: user: 128.26 s, system: 2.91 s, elapsed: 131.21 s 2017-09-19 10:36:11.069 BST [71241] LOG: finished writing run 4/3 to tape 2: CPU: user: 129.51 s, system: 3.22 s, elapsed: 132.76 s 2017-09-19 10:36:12.281 BST [71237] LOG: finished quicksort of run 0/3: CPU: user: 131.21 s, system: 2.68 s, elapsed: 133.98 s 2017-09-19 10:36:12.281 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:36:16.590 BST [71244] LOG: starting quicksort of run 7/4: CPU: user: 134.75 s, system: 3.45 s, elapsed: 138.28 s 2017-09-19 10:36:19.698 BST [71237] LOG: finished writing run 0/3 to tape 2: CPU: user: 138.46 s, system: 2.84 s, elapsed: 141.39 s 2017-09-19 10:36:19.698 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:36:23.838 BST [71238] LOG: starting quicksort of run 1/4: CPU: user: 142.73 s, system: 2.73 s, elapsed: 145.53 s 2017-09-19 10:36:24.215 BST [71243] LOG: starting quicksort of run 5/4: CPU: user: 142.13 s, system: 3.70 s, elapsed: 145.90 s 2017-09-19 10:36:26.771 BST [71242] LOG: starting quicksort of run 6/4: CPU: user: 144.51 s, system: 3.87 s, elapsed: 148.46 s 2017-09-19 10:36:28.540 BST [71240] LOG: starting quicksort of run 3/4: CPU: user: 146.71 s, system: 3.48 s, elapsed: 150.23 s 2017-09-19 10:36:29.766 BST [71241] LOG: starting quicksort of run 4/4: CPU: user: 147.75 s, system: 3.66 s, elapsed: 151.46 s 2017-09-19 10:36:30.110 BST [71239] LOG: starting quicksort of run 2/4: CPU: user: 148.23 s, system: 3.52 s, elapsed: 151.80 s 2017-09-19 10:36:32.727 BST [71244] LOG: finished quicksort of run 7/4: CPU: user: 150.87 s, system: 3.46 s, elapsed: 154.41 s 2017-09-19 10:36:38.277 BST [71244] LOG: finished writing run 7/4 to tape 3: CPU: user: 156.17 s, system: 3.70 s, elapsed: 159.96 s 2017-09-19 10:36:40.813 BST [71237] LOG: starting quicksort of run 0/4: CPU: user: 159.06 s, system: 3.36 s, elapsed: 162.51 s 2017-09-19 10:36:40.813 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:36:40.851 BST [71243] LOG: finished quicksort of run 5/4: CPU: user: 158.59 s, system: 3.87 s, elapsed: 162.54 s 2017-09-19 10:36:42.097 BST [71238] LOG: finished quicksort of run 1/4: CPU: user: 160.93 s, system: 2.79 s, elapsed: 163.79 s 2017-09-19 10:36:43.420 BST [71242] LOG: finished quicksort of run 6/4: CPU: user: 160.96 s, system: 4.07 s, elapsed: 165.11 s 2017-09-19 10:36:45.708 BST [71240] LOG: finished quicksort of run 3/4: CPU: user: 163.59 s, system: 3.77 s, elapsed: 167.40 s 2017-09-19 10:36:46.172 BST [71241] LOG: finished quicksort of run 4/4: CPU: user: 164.06 s, system: 3.76 s, elapsed: 167.86 s 2017-09-19 10:36:47.389 BST [71239] LOG: finished quicksort of run 2/4: CPU: user: 165.38 s, system: 3.59 s, elapsed: 169.08 s 2017-09-19 10:36:47.808 BST [71238] LOG: finished writing run 1/4 to tape 3: CPU: user: 166.40 s, system: 3.02 s, elapsed: 169.50 s 2017-09-19 10:36:48.495 BST [71243] LOG: finished writing run 5/4 to tape 3: CPU: user: 165.81 s, system: 4.29 s, elapsed: 170.18 s 2017-09-19 10:36:49.434 BST [71242] LOG: finished writing run 6/4 to tape 3: CPU: user: 166.76 s, system: 4.28 s, elapsed: 171.12 s 2017-09-19 10:36:52.491 BST [71240] LOG: finished writing run 3/4 to tape 3: CPU: user: 170.04 s, system: 4.10 s, elapsed: 174.18 s 2017-09-19 10:36:52.613 BST [71241] LOG: finished writing run 4/4 to tape 3: CPU: user: 170.22 s, system: 4.04 s, elapsed: 174.30 s 2017-09-19 10:36:53.127 BST [71239] LOG: finished writing run 2/4 to tape 3: CPU: user: 170.93 s, system: 3.78 s, elapsed: 174.82 s 2017-09-19 10:36:54.910 BST [71244] LOG: starting quicksort of run 7/5: CPU: user: 172.34 s, system: 4.15 s, elapsed: 176.60 s 2017-09-19 10:37:01.145 BST [71237] LOG: finished quicksort of run 0/4: CPU: user: 179.33 s, system: 3.42 s, elapsed: 182.84 s 2017-09-19 10:37:01.145 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:37:06.351 BST [71238] LOG: starting quicksort of run 1/5: CPU: user: 184.56 s, system: 3.40 s, elapsed: 188.04 s 2017-09-19 10:37:06.379 BST [71243] LOG: starting quicksort of run 5/5: CPU: user: 183.23 s, system: 4.75 s, elapsed: 188.07 s 2017-09-19 10:37:06.731 BST [71242] LOG: starting quicksort of run 6/5: CPU: user: 183.68 s, system: 4.64 s, elapsed: 188.42 s 2017-09-19 10:37:08.941 BST [71237] LOG: finished writing run 0/4 to tape 3: CPU: user: 186.83 s, system: 3.69 s, elapsed: 190.64 s 2017-09-19 10:37:08.941 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:37:10.957 BST [71240] LOG: starting quicksort of run 3/5: CPU: user: 188.01 s, system: 4.58 s, elapsed: 192.65 s 2017-09-19 10:37:11.813 BST [71239] LOG: starting quicksort of run 2/5: CPU: user: 189.20 s, system: 4.19 s, elapsed: 193.50 s 2017-09-19 10:37:12.378 BST [71244] LOG: finished quicksort of run 7/5: CPU: user: 189.70 s, system: 4.26 s, elapsed: 194.07 s 2017-09-19 10:37:12.816 BST [71241] LOG: starting quicksort of run 4/5: CPU: user: 189.93 s, system: 4.52 s, elapsed: 194.51 s 2017-09-19 10:37:18.083 BST [71244] LOG: finished writing run 7/5 to tape 4: CPU: user: 195.18 s, system: 4.48 s, elapsed: 199.77 s 2017-09-19 10:37:22.496 BST [71242] LOG: finished quicksort of run 6/5: CPU: user: 199.38 s, system: 4.70 s, elapsed: 204.18 s 2017-09-19 10:37:23.255 BST [71243] LOG: finished quicksort of run 5/5: CPU: user: 199.79 s, system: 5.06 s, elapsed: 204.94 s 2017-09-19 10:37:23.743 BST [71238] LOG: finished quicksort of run 1/5: CPU: user: 201.85 s, system: 3.50 s, elapsed: 205.43 s 2017-09-19 10:37:26.848 BST [71240] LOG: finished quicksort of run 3/5: CPU: user: 203.86 s, system: 4.62 s, elapsed: 208.54 s 2017-09-19 10:37:27.351 BST [71239] LOG: finished quicksort of run 2/5: CPU: user: 204.73 s, system: 4.20 s, elapsed: 209.04 s 2017-09-19 10:37:28.276 BST [71237] LOG: starting quicksort of run 0/5: CPU: user: 205.72 s, system: 4.14 s, elapsed: 209.97 s 2017-09-19 10:37:28.276 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:37:28.605 BST [71242] LOG: finished writing run 6/5 to tape 4: CPU: user: 205.34 s, system: 4.85 s, elapsed: 210.29 s 2017-09-19 10:37:29.396 BST [71243] LOG: finished writing run 5/5 to tape 4: CPU: user: 205.72 s, system: 5.27 s, elapsed: 211.08 s 2017-09-19 10:37:29.594 BST [71238] LOG: finished writing run 1/5 to tape 4: CPU: user: 207.42 s, system: 3.78 s, elapsed: 211.28 s 2017-09-19 10:37:30.673 BST [71241] LOG: finished quicksort of run 4/5: CPU: user: 207.76 s, system: 4.55 s, elapsed: 212.36 s 2017-09-19 10:37:32.783 BST [71239] LOG: finished writing run 2/5 to tape 4: CPU: user: 209.99 s, system: 4.37 s, elapsed: 214.47 s 2017-09-19 10:37:34.734 BST [71240] LOG: finished writing run 3/5 to tape 4: CPU: user: 211.21 s, system: 5.16 s, elapsed: 216.42 s 2017-09-19 10:37:34.806 BST [71244] LOG: starting quicksort of run 7/6: CPU: user: 211.40 s, system: 4.98 s, elapsed: 216.49 s 2017-09-19 10:37:37.483 BST [71241] LOG: finished writing run 4/5 to tape 4: CPU: user: 214.26 s, system: 4.84 s, elapsed: 219.17 s 2017-09-19 10:37:45.502 BST [71242] LOG: starting quicksort of run 6/6: CPU: user: 221.91 s, system: 5.17 s, elapsed: 227.19 s 2017-09-19 10:37:46.991 BST [71243] LOG: starting quicksort of run 5/6: CPU: user: 222.70 s, system: 5.88 s, elapsed: 228.68 s 2017-09-19 10:37:47.563 BST [71237] LOG: finished quicksort of run 0/5: CPU: user: 224.98 s, system: 4.17 s, elapsed: 229.26 s 2017-09-19 10:37:47.563 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:37:48.210 BST [71238] LOG: starting quicksort of run 1/6: CPU: user: 225.64 s, system: 4.17 s, elapsed: 229.90 s 2017-09-19 10:37:50.262 BST [71239] LOG: starting quicksort of run 2/6: CPU: user: 226.94 s, system: 4.89 s, elapsed: 231.95 s 2017-09-19 10:37:51.612 BST [71240] LOG: starting quicksort of run 3/6: CPU: user: 227.61 s, system: 5.63 s, elapsed: 233.30 s 2017-09-19 10:37:53.219 BST [71244] LOG: finished quicksort of run 7/6: CPU: user: 229.74 s, system: 5.05 s, elapsed: 234.91 s 2017-09-19 10:37:54.425 BST [71237] LOG: finished writing run 0/5 to tape 4: CPU: user: 231.57 s, system: 4.43 s, elapsed: 236.12 s 2017-09-19 10:37:54.425 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:37:56.034 BST [71241] LOG: starting quicksort of run 4/6: CPU: user: 232.20 s, system: 5.41 s, elapsed: 237.72 s 2017-09-19 10:37:59.037 BST [71244] LOG: finished writing run 7/6 to tape 5: CPU: user: 235.32 s, system: 5.29 s, elapsed: 240.72 s 2017-09-19 10:38:01.594 BST [71242] LOG: finished quicksort of run 6/6: CPU: user: 238.00 s, system: 5.17 s, elapsed: 243.28 s 2017-09-19 10:38:03.579 BST [71243] LOG: finished quicksort of run 5/6: CPU: user: 239.22 s, system: 5.95 s, elapsed: 245.27 s 2017-09-19 10:38:07.130 BST [71239] LOG: finished quicksort of run 2/6: CPU: user: 243.80 s, system: 4.90 s, elapsed: 248.82 s 2017-09-19 10:38:08.491 BST [71238] LOG: finished quicksort of run 1/6: CPU: user: 245.87 s, system: 4.22 s, elapsed: 250.18 s 2017-09-19 10:38:09.896 BST [71242] LOG: finished writing run 6/6 to tape 5: CPU: user: 245.95 s, system: 5.51 s, elapsed: 251.58 s 2017-09-19 10:38:11.047 BST [71243] LOG: finished writing run 5/6 to tape 5: CPU: user: 246.41 s, system: 6.22 s, elapsed: 252.74 s 2017-09-19 10:38:11.259 BST [71241] LOG: finished quicksort of run 4/6: CPU: user: 247.40 s, system: 5.42 s, elapsed: 252.95 s 2017-09-19 10:38:11.842 BST [71240] LOG: finished quicksort of run 3/6: CPU: user: 247.76 s, system: 5.69 s, elapsed: 253.53 s 2017-09-19 10:38:13.053 BST [71239] LOG: finished writing run 2/6 to tape 5: CPU: user: 249.50 s, system: 5.12 s, elapsed: 254.74 s 2017-09-19 10:38:13.475 BST [71237] LOG: starting quicksort of run 0/6: CPU: user: 250.22 s, system: 4.83 s, elapsed: 255.17 s 2017-09-19 10:38:13.475 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:38:14.351 BST [71238] LOG: finished writing run 1/6 to tape 5: CPU: user: 251.56 s, system: 4.39 s, elapsed: 256.04 s 2017-09-19 10:38:18.124 BST [71240] LOG: finished writing run 3/6 to tape 5: CPU: user: 253.93 s, system: 5.80 s, elapsed: 259.81 s 2017-09-19 10:38:18.154 BST [71244] LOG: starting quicksort of run 7/7: CPU: user: 253.99 s, system: 5.74 s, elapsed: 259.84 s 2017-09-19 10:38:18.913 BST [71241] LOG: finished writing run 4/6 to tape 5: CPU: user: 254.89 s, system: 5.56 s, elapsed: 260.60 s 2017-09-19 10:38:28.153 BST [71243] LOG: starting quicksort of run 5/7: CPU: user: 263.16 s, system: 6.57 s, elapsed: 269.84 s 2017-09-19 10:38:28.439 BST [71242] LOG: starting quicksort of run 6/7: CPU: user: 263.92 s, system: 6.07 s, elapsed: 270.13 s 2017-09-19 10:38:30.527 BST [71239] LOG: starting quicksort of run 2/7: CPU: user: 266.55 s, system: 5.54 s, elapsed: 272.22 s 2017-09-19 10:38:32.147 BST [71238] LOG: starting quicksort of run 1/7: CPU: user: 268.94 s, system: 4.80 s, elapsed: 273.84 s 2017-09-19 10:38:33.408 BST [71237] LOG: finished quicksort of run 0/6: CPU: user: 270.11 s, system: 4.87 s, elapsed: 275.10 s 2017-09-19 10:38:33.408 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:38:34.853 BST [71244] LOG: finished quicksort of run 7/7: CPU: user: 270.63 s, system: 5.79 s, elapsed: 276.54 s 2017-09-19 10:38:36.123 BST [71240] LOG: starting quicksort of run 3/7: CPU: user: 271.53 s, system: 6.20 s, elapsed: 277.81 s 2017-09-19 10:38:37.981 BST [71241] LOG: starting quicksort of run 4/7: CPU: user: 273.57 s, system: 5.93 s, elapsed: 279.67 s 2017-09-19 10:38:41.526 BST [71237] LOG: finished writing run 0/6 to tape 5: CPU: user: 277.84 s, system: 5.09 s, elapsed: 283.22 s 2017-09-19 10:38:41.526 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:38:41.553 BST [71244] LOG: finished writing run 7/7 to tape 6: CPU: user: 276.95 s, system: 6.00 s, elapsed: 283.24 s 2017-09-19 10:38:45.463 BST [71242] LOG: finished quicksort of run 6/7: CPU: user: 280.83 s, system: 6.19 s, elapsed: 287.15 s 2017-09-19 10:38:45.558 BST [71243] LOG: finished quicksort of run 5/7: CPU: user: 280.35 s, system: 6.78 s, elapsed: 287.25 s 2017-09-19 10:38:47.076 BST [71239] LOG: finished quicksort of run 2/7: CPU: user: 283.08 s, system: 5.56 s, elapsed: 288.77 s 2017-09-19 10:38:47.218 BST [71238] LOG: finished quicksort of run 1/7: CPU: user: 284.01 s, system: 4.81 s, elapsed: 288.91 s 2017-09-19 10:38:51.575 BST [71242] LOG: finished writing run 6/7 to tape 6: CPU: user: 286.64 s, system: 6.46 s, elapsed: 293.26 s 2017-09-19 10:38:52.747 BST [71239] LOG: finished writing run 2/7 to tape 6: CPU: user: 288.55 s, system: 5.75 s, elapsed: 294.44 s 2017-09-19 10:38:52.770 BST [71243] LOG: finished writing run 5/7 to tape 6: CPU: user: 287.25 s, system: 7.08 s, elapsed: 294.46 s 2017-09-19 10:38:52.899 BST [71240] LOG: finished quicksort of run 3/7: CPU: user: 288.23 s, system: 6.25 s, elapsed: 294.59 s 2017-09-19 10:38:52.988 BST [71238] LOG: finished writing run 1/7 to tape 6: CPU: user: 289.55 s, system: 5.02 s, elapsed: 294.68 s 2017-09-19 10:38:53.661 BST [71241] LOG: finished quicksort of run 4/7: CPU: user: 289.25 s, system: 5.93 s, elapsed: 295.35 s 2017-09-19 10:38:58.017 BST [71244] LOG: starting quicksort of run 7/8: CPU: user: 293.10 s, system: 6.30 s, elapsed: 299.70 s 2017-09-19 10:38:59.716 BST [71237] LOG: starting quicksort of run 0/7: CPU: user: 295.63 s, system: 5.47 s, elapsed: 301.41 s 2017-09-19 10:38:59.716 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:39:00.778 BST [71240] LOG: finished writing run 3/7 to tape 6: CPU: user: 295.72 s, system: 6.63 s, elapsed: 302.47 s 2017-09-19 10:39:02.114 BST [71241] LOG: finished writing run 4/7 to tape 6: CPU: user: 297.43 s, system: 6.21 s, elapsed: 303.80 s 2017-09-19 10:39:08.690 BST [71242] LOG: starting quicksort of run 6/8: CPU: user: 303.27 s, system: 6.94 s, elapsed: 310.38 s 2017-09-19 10:39:10.827 BST [71239] LOG: starting quicksort of run 2/8: CPU: user: 306.01 s, system: 6.37 s, elapsed: 312.52 s 2017-09-19 10:39:10.834 BST [71238] LOG: starting quicksort of run 1/8: CPU: user: 307.01 s, system: 5.41 s, elapsed: 312.52 s 2017-09-19 10:39:11.138 BST [71243] LOG: starting quicksort of run 5/8: CPU: user: 305.18 s, system: 7.51 s, elapsed: 312.83 s 2017-09-19 10:39:13.988 BST [71244] LOG: finished quicksort of run 7/8: CPU: user: 309.03 s, system: 6.34 s, elapsed: 315.68 s 2017-09-19 10:39:19.418 BST [71241] LOG: starting quicksort of run 4/8: CPU: user: 314.23 s, system: 6.70 s, elapsed: 321.11 s 2017-09-19 10:39:19.468 BST [71240] LOG: starting quicksort of run 3/8: CPU: user: 313.95 s, system: 7.09 s, elapsed: 321.16 s 2017-09-19 10:39:19.563 BST [71244] LOG: finished writing run 7/8 to tape 7: CPU: user: 314.44 s, system: 6.50 s, elapsed: 321.25 s 2017-09-19 10:39:20.296 BST [71237] LOG: finished quicksort of run 0/7: CPU: user: 316.19 s, system: 5.49 s, elapsed: 321.99 s 2017-09-19 10:39:20.296 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:39:25.834 BST [71242] LOG: finished quicksort of run 6/8: CPU: user: 320.36 s, system: 7.00 s, elapsed: 327.52 s 2017-09-19 10:39:27.380 BST [71237] LOG: finished writing run 0/7 to tape 6: CPU: user: 323.10 s, system: 5.65 s, elapsed: 329.08 s 2017-09-19 10:39:27.380 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:39:28.042 BST [71243] LOG: finished quicksort of run 5/8: CPU: user: 322.02 s, system: 7.56 s, elapsed: 329.73 s 2017-09-19 10:39:28.378 BST [71239] LOG: finished quicksort of run 2/8: CPU: user: 323.52 s, system: 6.41 s, elapsed: 330.07 s 2017-09-19 10:39:28.643 BST [71238] LOG: finished quicksort of run 1/8: CPU: user: 324.82 s, system: 5.41 s, elapsed: 330.33 s 2017-09-19 10:39:34.347 BST [71242] LOG: finished writing run 6/8 to tape 7: CPU: user: 328.45 s, system: 7.40 s, elapsed: 336.03 s 2017-09-19 10:39:34.365 BST [71239] LOG: finished writing run 2/8 to tape 7: CPU: user: 329.33 s, system: 6.58 s, elapsed: 336.05 s 2017-09-19 10:39:34.477 BST [71238] LOG: finished writing run 1/8 to tape 7: CPU: user: 330.39 s, system: 5.67 s, elapsed: 336.17 s 2017-09-19 10:39:35.145 BST [71243] LOG: finished writing run 5/8 to tape 7: CPU: user: 328.80 s, system: 7.88 s, elapsed: 336.83 s 2017-09-19 10:39:36.263 BST [71244] LOG: starting quicksort of run 7/9: CPU: user: 330.81 s, system: 6.81 s, elapsed: 337.95 s 2017-09-19 10:39:36.898 BST [71240] LOG: finished quicksort of run 3/8: CPU: user: 331.38 s, system: 7.09 s, elapsed: 338.59 s 2017-09-19 10:39:36.918 BST [71241] LOG: finished quicksort of run 4/8: CPU: user: 331.68 s, system: 6.75 s, elapsed: 338.61 s 2017-09-19 10:39:41.719 BST [71239] LOG: performsort of 2 starting: CPU: user: 336.63 s, system: 6.64 s, elapsed: 343.41 s 2017-09-19 10:39:41.719 BST [71238] LOG: performsort of 1 starting: CPU: user: 337.43 s, system: 5.87 s, elapsed: 343.41 s 2017-09-19 10:39:41.719 BST [71239] LOG: starting quicksort of run 2/9: CPU: user: 336.63 s, system: 6.64 s, elapsed: 343.41 s 2017-09-19 10:39:41.719 BST [71243] LOG: performsort of 5 starting: CPU: user: 335.21 s, system: 8.04 s, elapsed: 343.41 s 2017-09-19 10:39:41.719 BST [71242] LOG: performsort of 6 starting: CPU: user: 335.62 s, system: 7.60 s, elapsed: 343.41 s 2017-09-19 10:39:41.719 BST [71238] LOG: starting quicksort of run 1/9: CPU: user: 337.43 s, system: 5.87 s, elapsed: 343.41 s 2017-09-19 10:39:41.719 BST [71237] LOG: performsort of 0 starting: CPU: user: 337.03 s, system: 6.06 s, elapsed: 343.42 s 2017-09-19 10:39:41.719 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:39:41.719 BST [71243] LOG: starting quicksort of run 5/9: CPU: user: 335.21 s, system: 8.04 s, elapsed: 343.41 s 2017-09-19 10:39:41.719 BST [71242] LOG: starting quicksort of run 6/9: CPU: user: 335.62 s, system: 7.60 s, elapsed: 343.41 s 2017-09-19 10:39:41.719 BST [71237] LOG: starting quicksort of run 0/8: CPU: user: 337.03 s, system: 6.06 s, elapsed: 343.42 s 2017-09-19 10:39:41.719 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:39:43.587 BST [71240] LOG: finished writing run 3/8 to tape 7: CPU: user: 337.86 s, system: 7.30 s, elapsed: 345.28 s 2017-09-19 10:39:43.588 BST [71240] LOG: performsort of 3 starting: CPU: user: 337.86 s, system: 7.30 s, elapsed: 345.28 s 2017-09-19 10:39:43.588 BST [71240] LOG: starting quicksort of run 3/9: CPU: user: 337.86 s, system: 7.30 s, elapsed: 345.28 s 2017-09-19 10:39:43.588 BST [71240] LOG: finished quicksort of run 3/9: CPU: user: 337.86 s, system: 7.30 s, elapsed: 345.28 s 2017-09-19 10:39:43.588 BST [71240] LOG: finished writing run 3/9 to tape 8: CPU: user: 337.86 s, system: 7.30 s, elapsed: 345.28 s 2017-09-19 10:39:43.620 BST [71240] LOG: 3 using 931976 KB of memory for read buffers among 9 input tapes 2017-09-19 10:39:43.898 BST [71241] LOG: finished writing run 4/8 to tape 7: CPU: user: 338.43 s, system: 6.98 s, elapsed: 345.59 s 2017-09-19 10:39:43.899 BST [71241] LOG: performsort of 4 starting: CPU: user: 338.43 s, system: 6.98 s, elapsed: 345.59 s 2017-09-19 10:39:43.899 BST [71241] LOG: starting quicksort of run 4/9: CPU: user: 338.43 s, system: 6.98 s, elapsed: 345.59 s 2017-09-19 10:39:43.899 BST [71241] LOG: finished quicksort of run 4/9: CPU: user: 338.43 s, system: 6.98 s, elapsed: 345.59 s 2017-09-19 10:39:43.899 BST [71241] LOG: finished writing run 4/9 to tape 8: CPU: user: 338.43 s, system: 6.98 s, elapsed: 345.59 s 2017-09-19 10:39:43.936 BST [71241] LOG: 4 using 931976 KB of memory for read buffers among 9 input tapes 2017-09-19 10:39:47.656 BST [71243] LOG: finished quicksort of run 5/9: CPU: user: 341.13 s, system: 8.06 s, elapsed: 349.34 s 2017-09-19 10:39:48.338 BST [71238] LOG: finished quicksort of run 1/9: CPU: user: 344.05 s, system: 5.87 s, elapsed: 350.03 s 2017-09-19 10:39:48.859 BST [71239] LOG: finished quicksort of run 2/9: CPU: user: 343.77 s, system: 6.64 s, elapsed: 350.55 s 2017-09-19 10:39:49.472 BST [71242] LOG: finished quicksort of run 6/9: CPU: user: 343.35 s, system: 7.62 s, elapsed: 351.16 s 2017-09-19 10:39:50.505 BST [71243] LOG: finished writing run 5/9 to tape 8: CPU: user: 343.89 s, system: 8.15 s, elapsed: 352.19 s 2017-09-19 10:39:50.554 BST [71243] LOG: 5 using 931976 KB of memory for read buffers among 9 input tapes 2017-09-19 10:39:50.851 BST [71238] LOG: finished writing run 1/9 to tape 8: CPU: user: 346.44 s, system: 5.99 s, elapsed: 352.54 s 2017-09-19 10:39:50.869 BST [71238] LOG: 1 using 931976 KB of memory for read buffers among 9 input tapes 2017-09-19 10:39:51.481 BST [71239] LOG: finished writing run 2/9 to tape 8: CPU: user: 346.29 s, system: 6.74 s, elapsed: 353.17 s 2017-09-19 10:39:51.510 BST [71239] LOG: 2 using 931976 KB of memory for read buffers among 9 input tapes 2017-09-19 10:39:51.898 BST [71244] LOG: finished quicksort of run 7/9: CPU: user: 346.44 s, system: 6.82 s, elapsed: 353.58 s 2017-09-19 10:39:51.989 BST [71242] LOG: finished writing run 6/9 to tape 8: CPU: user: 345.80 s, system: 7.69 s, elapsed: 353.68 s 2017-09-19 10:39:52.030 BST [71242] LOG: 6 using 931976 KB of memory for read buffers among 9 input tapes 2017-09-19 10:39:54.331 BST [71237] LOG: finished quicksort of run 0/8: CPU: user: 349.64 s, system: 6.06 s, elapsed: 356.03 s 2017-09-19 10:39:54.331 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:39:58.714 BST [71244] LOG: finished writing run 7/9 to tape 8: CPU: user: 352.99 s, system: 7.08 s, elapsed: 360.40 s 2017-09-19 10:39:58.714 BST [71244] LOG: performsort of 7 starting: CPU: user: 352.99 s, system: 7.08 s, elapsed: 360.40 s 2017-09-19 10:39:58.714 BST [71244] LOG: starting quicksort of run 7/10: CPU: user: 352.99 s, system: 7.08 s, elapsed: 360.40 s 2017-09-19 10:39:58.714 BST [71244] LOG: finished quicksort of run 7/10: CPU: user: 352.99 s, system: 7.08 s, elapsed: 360.40 s 2017-09-19 10:39:58.714 BST [71244] LOG: finished writing run 7/10 to tape 9: CPU: user: 352.99 s, system: 7.08 s, elapsed: 360.40 s 2017-09-19 10:39:58.752 BST [71244] LOG: 7 using 931967 KB of memory for read buffers among 10 input tapes 2017-09-19 10:39:59.020 BST [71237] LOG: finished writing run 0/8 to tape 7: CPU: user: 354.13 s, system: 6.25 s, elapsed: 360.72 s 2017-09-19 10:39:59.020 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:39:59.041 BST [71237] LOG: 0 using 1048494 KB of memory for read buffers among 8 input tapes 2017-09-19 10:39:59.041 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:40:46.098 BST [71241] LOG: 4 finished 9-way merge step: CPU: user: 398.60 s, system: 8.17 s, elapsed: 407.79 s 2017-09-19 10:40:46.182 BST [71241] LOG: performsort of 4 done: CPU: user: 398.68 s, system: 8.17 s, elapsed: 407.87 s 2017-09-19 10:40:48.982 BST [71240] LOG: 3 finished 9-way merge step: CPU: user: 400.91 s, system: 8.79 s, elapsed: 410.67 s 2017-09-19 10:40:49.072 BST [71240] LOG: performsort of 3 done: CPU: user: 400.97 s, system: 8.82 s, elapsed: 410.76 s 2017-09-19 10:40:56.451 BST [71238] LOG: 1 finished 9-way merge step: CPU: user: 409.05 s, system: 7.56 s, elapsed: 418.14 s 2017-09-19 10:40:56.550 BST [71238] LOG: performsort of 1 done: CPU: user: 409.09 s, system: 7.62 s, elapsed: 418.24 s 2017-09-19 10:40:59.353 BST [71242] LOG: 6 finished 9-way merge step: CPU: user: 410.26 s, system: 9.18 s, elapsed: 421.04 s 2017-09-19 10:40:59.463 BST [71242] LOG: performsort of 6 done: CPU: user: 410.34 s, system: 9.21 s, elapsed: 421.15 s 2017-09-19 10:40:59.497 BST [71239] LOG: 2 finished 9-way merge step: CPU: user: 411.40 s, system: 8.23 s, elapsed: 421.19 s 2017-09-19 10:40:59.561 BST [71239] LOG: performsort of 2 done: CPU: user: 411.43 s, system: 8.26 s, elapsed: 421.25 s 2017-09-19 10:40:59.705 BST [71243] LOG: 5 finished 9-way merge step: CPU: user: 410.03 s, system: 9.80 s, elapsed: 421.39 s 2017-09-19 10:40:59.841 BST [71243] LOG: performsort of 5 done: CPU: user: 410.11 s, system: 9.85 s, elapsed: 421.53 s 2017-09-19 10:41:04.772 BST [71237] LOG: 0 finished 8-way merge step: CPU: user: 417.11 s, system: 7.62 s, elapsed: 426.47 s 2017-09-19 10:41:04.772 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:41:04.919 BST [71237] LOG: performsort of 0 done: CPU: user: 417.25 s, system: 7.63 s, elapsed: 426.62 s 2017-09-19 10:41:04.919 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:41:08.702 BST [71244] LOG: 7 finished 10-way merge step: CPU: user: 419.90 s, system: 8.59 s, elapsed: 430.39 s 2017-09-19 10:41:08.702 BST [71237] LOG: performsort of -1 starting: CPU: user: 417.25 s, system: 7.63 s, elapsed: 430.40 s 2017-09-19 10:41:08.702 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:41:08.702 BST [71237] LOG: -1 using 8388526 KB of memory for read buffers among 8 input tapes 2017-09-19 10:41:08.702 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:41:08.854 BST [71244] LOG: performsort of 7 done: CPU: user: 420.00 s, system: 8.64 s, elapsed: 430.54 s 2017-09-19 10:41:12.070 BST [71237] LOG: performsort done (except 8-way final merge): CPU: user: 418.08 s, system: 10.17 s, elapsed: 433.77 s 2017-09-19 10:41:12.070 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint); 2017-09-19 10:53:15.309 BST [71237] LOG: parallel external sort ended, 2446245 disk blocks used: CPU: user: 1039.59 s, system: 33.43 s, elapsed: 1157.01 s 2017-09-19 10:53:15.309 BST [71237] STATEMENT: CREATE INDEX serial_idx ON parallel_sort_test (randint);