X-Original-To: pgsql-performance-postgresql.org@localhost.postgresql.org Received: from localhost (av.hub.org [200.46.204.144]) by postgresql.org (Postfix) with ESMTP id 170629DCC61 for ; Wed, 15 Feb 2006 17:49:02 -0400 (AST) Received: from postgresql.org ([200.46.204.71]) by localhost (av.hub.org [200.46.204.144]) (amavisd-new, port 10024) with ESMTP id 28510-02 for ; Wed, 15 Feb 2006 17:49:03 -0400 (AST) X-Greylist: from auto-whitelisted by SQLgrey- Received: from sss.pgh.pa.us (sss.pgh.pa.us [66.207.139.130]) by postgresql.org (Postfix) with ESMTP id 821B09DCC2D for ; Wed, 15 Feb 2006 17:48:59 -0400 (AST) Received: from sss2.sss.pgh.pa.us (tgl@localhost [127.0.0.1]) by sss.pgh.pa.us (8.13.1/8.13.1) with ESMTP id k1FLmumk019976; Wed, 15 Feb 2006 16:48:56 -0500 (EST) To: Simon Riggs cc: Gary Doades , pgsql-performance@postgresql.org Subject: Re: Strange Create Index behaviour In-reply-to: <1140038847.12131.155.camel@localhost.localdomain> References: <43F38867.6010701@gpdnet.co.uk> <1140038847.12131.155.camel@localhost.localdomain> Comments: In-reply-to Simon Riggs message dated "Wed, 15 Feb 2006 21:27:27 +0000" Date: Wed, 15 Feb 2006 16:48:56 -0500 Message-ID: <19975.1140040136@sss.pgh.pa.us> From: Tom Lane X-Virus-Scanned: by amavisd-new at hub.org X-Spam-Status: No, score=0.11 required=5 tests=[AWL=0.110] X-Spam-Score: 0.11 X-Spam-Level: X-Archive-Number: 200602/222 X-Sequence-Number: 17208 Simon Riggs 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