On Sun, 2005-10-02 at 19:43 +0100, Simon Riggs wrote:
> 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.

> Best Regards, Simon Riggs


---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

Simon Riggs <simon@2ndquadrant.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

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

On Mon, 2005-10-03 at 18:59 -0400, Tom Lane wrote:
> Simon Riggs <simon@2ndquadrant.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


---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

Tom Lane <tgl@sss.pgh.pa.us> writes:

> 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

I'm not actually involved in this so maybe I'm completely off base here. But
wouldn't you want to know how many tuples are being sorted and how many data
are being written in these runs in order to be able to actually make sense of
these timing measurements?

Otherwise you would never know whether the results people will send you are
really comparable. And even if you're testing things in a well controlled
environments you'll never know if you missed something and you're comparing
two incomparable results.

--
greg


---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

Greg Stark <gsstark@mit.edu> writes:
> I'm not actually involved in this so maybe I'm completely off base here. But
> wouldn't you want to know how many tuples are being sorted and how many data
> are being written in these runs in order to be able to actually make sense of
> these timing measurements?

In all plausible test cases you should be able to know the total number
of tuples being sorted independently. Counting the tuples processed in
each run would require extra per-tuple overhead, which I'd rather avoid
until proven necessary.

The total-data-volume aspect may or may not be interesting, not sure
yet. Let's see what we can learn from the present low-impact patch.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match