Simon Riggs <simon@xxxxxxxxxxxxxxx> writes: > Please enable trace_sort=on and then repeat tests and post the > accompanying log file. I did this on my Fedora machine with port/qsort.c, and got the results attached. Curiously, this run has the spikes in completely different places than the prior one did. So the random component of the test data is affecting the results quite a lot. There seems absolutely no doubt that we are looking at data-dependent qsort misbehavior, though. The CPU time eaten by performsort accounts for all but about 100 msec of the elapsed time reported on the psql side. regards, tom lane LOG: begin index sort: unique = f, workMem = 16384, randomAccess = f LOG: performsort starting: CPU 0.00s/0.15u sec elapsed 0.15 sec LOG: performsort done: CPU 0.00s/12.43u sec elapsed 12.44 sec LOG: internal sort ended, 9861 KB used: CPU 0.01s/12.51u sec elapsed 12.52 sec LOG: begin index sort: unique = f, workMem = 16384, randomAccess = f LOG: performsort starting: CPU 0.00s/0.14u sec elapsed 0.15 sec LOG: performsort done: CPU 0.00s/0.78u sec elapsed 0.78 sec LOG: internal sort ended, 9861 KB used: CPU 0.02s/0.85u sec elapsed 0.87 sec LOG: begin index sort: unique = f, workMem = 16384, randomAccess = f LOG: performsort starting: CPU 0.01s/0.14u sec elapsed 0.15 sec LOG: performsort done: CPU 0.01s/0.96u sec elapsed 0.97 sec LOG: internal sort ended, 9861 KB used: CPU 0.02s/1.03u sec elapsed 1.06 sec LOG: begin index sort: unique = f, workMem = 16384, randomAccess = f LOG: performsort starting: CPU 0.00s/0.14u sec elapsed 0.15 sec LOG: performsort done: CPU 0.00s/0.31u sec elapsed 0.32 sec LOG: internal sort ended, 9861 KB used: CPU 0.02s/0.38u sec elapsed 0.40 sec LOG: begin index sort: unique = f, workMem = 16384, randomAccess = f LOG: performsort starting: CPU 0.00s/0.14u sec elapsed 0.15 sec LOG: performsort done: CPU 0.00s/7.91u sec elapsed 7.92 sec LOG: internal sort ended, 9861 KB used: CPU 0.02s/7.99u sec elapsed 8.01 sec LOG: begin index sort: unique = f, workMem = 16384, randomAccess = f LOG: performsort starting: CPU 0.01s/0.13u sec elapsed 0.15 sec LOG: performsort done: CPU 0.01s/0.61u sec elapsed 0.63 sec LOG: internal sort ended, 9861 KB used: CPU 0.04s/0.67u sec elapsed 0.71 sec LOG: begin index sort: unique = f, workMem = 16384, randomAccess = f LOG: performsort starting: CPU 0.01s/0.13u sec elapsed 0.15 sec LOG: performsort done: CPU 0.01s/11.52u sec elapsed 11.54 sec LOG: internal sort ended, 9861 KB used: CPU 0.03s/11.59u sec elapsed 11.62 sec LOG: begin index sort: unique = f, workMem = 16384, randomAccess = f LOG: performsort starting: CPU 0.00s/0.14u sec elapsed 0.15 sec LOG: performsort done: CPU 0.00s/0.45u sec elapsed 0.46 sec LOG: internal sort ended, 9861 KB used: CPU 0.02s/0.55u sec elapsed 0.57 sec LOG: begin index sort: unique = f, workMem = 16384, randomAccess = f LOG: performsort starting: CPU 0.00s/0.14u sec elapsed 0.15 sec LOG: performsort done: CPU 0.00s/0.45u sec elapsed 0.46 sec LOG: internal sort ended, 9861 KB used: CPU 0.04s/0.54u sec elapsed 0.57 sec LOG: begin index sort: unique = f, workMem = 16384, randomAccess = f LOG: performsort starting: CPU 0.02s/0.12u sec elapsed 0.15 sec LOG: performsort done: CPU 0.02s/0.44u sec elapsed 0.46 sec LOG: internal sort ended, 9861 KB used: CPU 0.03s/0.55u sec elapsed 0.58 sec LOG: begin index sort: unique = f, workMem = 16384, randomAccess = f LOG: performsort starting: CPU 0.02s/0.13u sec elapsed 0.15 sec LOG: performsort done: CPU 0.02s/0.44u sec elapsed 0.46 sec LOG: internal sort ended, 9861 KB used: CPU 0.03s/0.54u sec elapsed 0.58 sec LOG: begin index sort: unique = f, workMem = 16384, randomAccess = f LOG: performsort starting: CPU 0.02s/0.13u sec elapsed 0.15 sec LOG: performsort done: CPU 0.02s/0.44u sec elapsed 0.46 sec LOG: internal sort ended, 9861 KB used: CPU 0.04s/0.54u sec elapsed 0.59 sec
