Re: External Sort timing debug statements

Simon Riggs <simon(at)2ndquadrant(dot)com> writes:
>> The following patch implements a fairly light set of timing statements
>> aimed at understanding external sort performance. There is no attempt to
>> alter the algorithms.

> Minor update of patch, use this version please.

Applied with revisions: I made it use the VacRUsage code so that we
could see both CPU and elapsed time, and moved the report points around
a bit. The output with trace_sort enabled looks like this:

NOTICE: begin tuple sort: nkeys = 1, workMem = 1024, randomAccess = t
NOTICE: switching to external sort: CPU 0.05s/0.10u sec elapsed 0.15 sec
NOTICE: finished writing run 1: CPU 0.14s/0.83u sec elapsed 0.99 sec
NOTICE: finished writing run 2: CPU 0.25s/1.67u sec elapsed 1.94 sec
NOTICE: finished writing run 3: CPU 0.37s/2.51u sec elapsed 2.90 sec
NOTICE: finished writing run 4: CPU 0.48s/3.36u sec elapsed 3.86 sec
...
NOTICE: finished writing run 45: CPU 5.06s/38.26u sec elapsed 43.55 sec
NOTICE: performsort starting: CPU 5.10s/38.62u sec elapsed 43.95 sec
NOTICE: finished writing run 46: CPU 5.11s/38.84u sec elapsed 44.18 sec
NOTICE: finished writing final run 47: CPU 5.11s/38.88u sec elapsed 44.22 sec
NOTICE: finished merge step: CPU 5.12s/39.02u sec elapsed 44.37 sec
NOTICE: finished merge step: CPU 5.13s/39.16u sec elapsed 44.53 sec
...
NOTICE: finished merge step: CPU 6.57s/67.78u sec elapsed 74.83 sec
NOTICE: performsort done: CPU 6.57s/67.78u sec elapsed 74.84 sec
NOTICE: sort ended: CPU 10.80s/74.73u sec elapsed 86.21 sec

regards, tom lane