From: Tom Lane <tgl@sss.pgh.pa.us>
To: Simon Riggs <simon@2ndquadrant.com>
Cc: Gary Doades <gpd@gpdnet.co.uk>
Cc: pgsql-performance@postgresql.org
Subject: Re: Strange Create Index behaviour
Date: Wed, 15 Feb 2006 16:48:56 -0500
Message-ID: <19975.1140040136@sss.pgh.pa.us> (raw)
In-Reply-To: <1140038847.12131.155.camel@localhost.localdomain>
References: <43F38867.6010701@gpdnet.co.uk>
<1140038847.12131.155.camel@localhost.localdomain>
Simon Riggs <simon@2ndquadrant.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
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-performance@postgresql.org
Cc: tgl@sss.pgh.pa.us, simon@2ndquadrant.com, gpd@gpdnet.co.uk
Subject: Re: Strange Create Index behaviour
In-Reply-To: <19975.1140040136@sss.pgh.pa.us>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox