Re: External Sort timing debug statements

On Mon, 2005-10-03 at 18:59 -0400, Tom Lane wrote:
> 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

Many thanks,

Best Regards, Simon Riggs