Re: Strange Create Index behaviour

Simon Riggs <simon(at)2ndquadrant(dot)com> 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