Обсуждение: Timing a query
Hi I am currently evaluating PostgreSQL for a project I'm working on and need to find out how long it takes to execute severaltypes of queries Can someone tell me if there is a way of getting the time a query has taken to run to display after the query results ( wherein gives the row count). Thank you Liz
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 > Can someone tell me if there is a way of getting the time a > query has taken to run to display after the query results ( > where in gives the row count). If you have a recent version of Postgresql, you can do an EXPLAIN ANALYZE before the actual query: EXPLAIN ANALYZE SELECT (*) FROM mytable WHERE foo=12; Alteratively, I wrote a small patch for psql that tells you how long every query you run takes. It may not work on your version: please always state which version you are running when posting a question. If you want to use my patch and it does not work with your version, let me know and I'll tweak it so it does. http://www.gtsm.com/postgres/microtiming.patch Greg Sabino Mullane greg@turnstep.com PGP Key: 0x14964AC8 200111271003 -----BEGIN PGP SIGNATURE----- Comment: http://www.gtsm.com/pgp.html iQA/AwUBPAOrcrybkGcUlkrIEQLjZQCfepfTDzVHkY3kO6j/po1FFRi4qVEAn1Ye Ih8pBO7jXx1lOTnp8ZoTD0oc =AU0N -----END PGP SIGNATURE-----
On Tue, 27 Nov 2001, Greg Sabino Mullane wrote: > If you have a recent version of Postgresql, you can do an > EXPLAIN ANALYZE before the actual query: How recent? 7.2 beta? I tried it on 7.1.3 and didn't have it. > Alteratively, I wrote a small patch for psql that tells > you how long every query you run takes. This seems to be such a commonly needed task. Shouldn't this be incorporated into psql? Could you include the output of "EXPLAIN ANALYZE" I would like to see what it gives.
On 27 Nov 2001, Elizabeth O'Neill wrote:
>Can someone tell me if there is a way of getting the time a query has taken
>to run to display after the query results ( where in gives the row
>count).
I am new myself and this is one of the things that I looked for without
much luck.
A couple of thoughts.
-You could restart postgresql and send the output of the server to a file.
Something like "pg_ctl restart >/var/log/pg.log". If you only have a few
users, or even better just you, then the output of that file will have the
type of ino you are looking for. However this won't work well if you have
different users since you won't easily know whose querie's result you are
looking at.
-You could create a "log table" where you do insert's before and after
your operation. I just started playing with this yesterday with mixed
results, but it would be something like:
insert into mergelogs values ('hraces', 'start load');
copy hraces from '/vol2/stmp1/hraces.txt' with NULL as '';
insert into mergelogs values ('hraces', 'completed load');
vacuum hraces;
insert into mergelogs values ('hraces', 'ran vacuum');
That worked for me, except that I wanted an insert coupled with a
begin/end transaction and that didn't work. The time of the insertion was
the same time as the time of the begin. In other words I was tying
something like
insert into mergelogs values ('hraces', 'start load');
begin transaction;
copy hraces from '/vol2/stmp1/hraces.txt' with NULL as '';
insert into mergelogs values ('hraces', 'completed load');
end transaction;
vacuum hraces;
insert into mergelogs values ('hraces', 'ran vacuum');
I wanted the "completed load" message to only appear if the copy worked,
but the problem was that the time been logged seemed the same as the time
the begin started.
IMPORTANT DETAIL: On the mergelogs table I have a field with
"DEFAULT now" so when I do an insert the time is recorded.
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 > How recent? 7.2 beta? > I tried it on 7.1.3 and didn't have it. Yes, it is a 7.2 feature. > Could you include the output of "EXPLAIN ANALYZE" I > would like to see what it gives. template1=# EXPLAIN ANALYZE SELECT foo,bar FROM baz; NOTICE: QUERY PLAN: Seq Scan on baz (cost=0.00..20.00 rows=1000 width=8) (actual time=0.01..0.01 rows=0 loops=1) Total runtime: 0.06 msec > This seems to be such a commonly needed task. Shouldn't this be > incorporated into psql? I still like my patch: it performs a little differently from the EXPLAIN ANALYZE function. You turn it on and off with the a "\m", and it records the time it takes everything to run, even things like index creation, which EXPLAIN ANALYZE does not handle. Plus, you don't have to go back and re-run the query if you want to time it: it simply presents the timing information after every query, until you turn the option off: template1=# SELECT count(*) FROM baz; count - ------- 15212 TOTAL TIME: 0.004665 template1=# CREATE INDEX foobar ON baz(waldo); CREATE TOTAL TIME: 0.011012 Greg Sabino Mullane greg@turnstep.com PGP Key: 0x14964AC8 200111271204 -----BEGIN PGP SIGNATURE----- Comment: http://www.turnstep.com/pgp.html iQA/AwUBPAPITrybkGcUlkrIEQI7qQCggBpgODxZ6Sv2iUqYrMYAffEDpUoAn2G+ W7PQpuxwrXzy/jXsRiOhxb8i =NxuD -----END PGP SIGNATURE-----
>> Can someone tell me if there is a way of getting the time a query has taken
>> to run to display after the query results ( where in gives the row
>> count).
You can get more info than you probably want by setting show_query_stats
to true (either with SET, or in postgresql.conf if you want it across
all backends). Also set debug_print_query to true. Now you'll get
stuff like this in the postmaster log:
DEBUG: query: select count(*) from tenk1 a, tenk1 b where a.unique1=b.unique2;
DEBUG: QUERY STATISTICS
! system usage stats:
! 2.128752 elapsed 1.300000 user 0.100000 system sec
! [1.380000 user 0.110000 sys total]
! 249/119 [249/122] filesystem blocks in/out
! 0/0 [0/43] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [6/7] messages rcvd/sent
! 82/51 [86/59] voluntary/involuntary context switches
! postgres usage stats:
! Shared blocks: 480 read, 0 written, buffer hit rate = 28.25%
! Local blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Direct blocks: 0 read, 0 written
You'll have to look at the code to interpret all of these numbers, but I
think the numbers in square brackets are the raw getrusage results (ie,
totals since backend startup) and the ones outside are the deltas over
the query. I've never looked to see exactly what's counted in the
"postgres usage stats".
regards, tom lane
> > This seems to be such a commonly needed task. Shouldn't this be > > incorporated into psql? > > I still like my patch: it performs a little differently from the > EXPLAIN ANALYZE function. You turn it on and off with the > a "\m", and it records the time it takes everything to run, > even things like index creation, which EXPLAIN ANALYZE does not > handle. Plus, you don't have to go back and re-run the query > if you want to time it: it simply presents the timing information > after every query, until you turn the option off: > > template1=# SELECT count(*) FROM baz; > > count > ------- > 15212 > > TOTAL TIME: 0.004665 > > template1=# CREATE INDEX foobar ON baz(waldo); > > CREATE > > TOTAL TIME: 0.011012 Yes, this does seem nice. -- Bruce Momjian | http://candle.pha.pa.us pgman@candle.pha.pa.us | (610) 853-3000 + If your life is a hard drive, | 830 Blythe Avenue + Christ can be your backup. | Drexel Hill, Pennsylvania 19026
this looks superb. one small question though; how do i apply the patch ? thanks, Steve ""Greg Sabino Mullane"" <greg@turnstep.com> wrote in message news:E168jiH-0002Jj-00@mclean.mail.mindspring.net... > > -----BEGIN PGP SIGNED MESSAGE----- > Hash: SHA1 > > > Can someone tell me if there is a way of getting the time a > > query has taken to run to display after the query results ( > > where in gives the row count). > > If you have a recent version of Postgresql, you can do an > EXPLAIN ANALYZE before the actual query: > > EXPLAIN ANALYZE SELECT (*) FROM mytable WHERE foo=12; > > Alteratively, I wrote a small patch for psql that tells > you how long every query you run takes. It may not work > on your version: please always state which version you > are running when posting a question. If you want to use my > patch and it does not work with your version, let me know > and I'll tweak it so it does. > > http://www.gtsm.com/postgres/microtiming.patch > > > Greg Sabino Mullane > greg@turnstep.com > PGP Key: 0x14964AC8 200111271003 > > > -----BEGIN PGP SIGNATURE----- > Comment: http://www.gtsm.com/pgp.html > > iQA/AwUBPAOrcrybkGcUlkrIEQLjZQCfepfTDzVHkY3kO6j/po1FFRi4qVEAn1Ye > Ih8pBO7jXx1lOTnp8ZoTD0oc > =AU0N > -----END PGP SIGNATURE----- > > > > > > ---------------------------(end of broadcast)--------------------------- > TIP 3: 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
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 > this looks superb. > > one small question though; how do i apply the patch ? I'll assume you have the sources for 7.1.3. I'll rewrite the patch for 7.2b3 in a little bit. Change to the top level of the postgresql source tree. > cd postgresql-7.1.3 Save the file at http://www.gtsm.com/postgres/microtiming.patch to a local file, perhaps named "microtiming.patch" > wget http://www.gtsm.com/postgres/microtiming.patch Patch the source with the file: > patch -bp0 < microtiming.patch If all goes well, you should see: patching file ./src/bin/psql/command.c patching file ./src/bin/psql/common.c patching file ./src/bin/psql/help.c patching file ./src/bin/psql/print.h patching file ./src/bin/psql/startup.c patching file ./src/bin/psql/tab-complete.c patching file ./doc/src/sgml/ref/psql-ref.sgml You can then run make from the top-level directory, or to avoid some output, cd to src/bin/psql and run make from there: >cd src/bin/psql; make When finished, you'll have a new psql binary in the src/bin/psql directory, which should have the microtiming stuff. Test it out before copying it over to anywhere permanent: >./psql template1=# select version(); version - - -------------------------------------------------------------- PostgreSQL 7.1.3 on i686-pc-linux-gnu, compiled by GCC 3.0.1 (1 row) template1=# \m Microsecond timing is on. template1=# select version(); version - - -------------------------------------------------------------- PostgreSQL 7.1.3 on i686-pc-linux-gnu, compiled by GCC 3.0.1 (1 row) TOTAL TIME: 0.001660 template1=# Greg Sabino Mullane greg@turnstep.com PGP Key: 0x14964AC8 200111281041 -----BEGIN PGP SIGNATURE----- Comment: http://www.turnstep.com/pgp.html iQA/AwUBPAUIGrybkGcUlkrIEQK8BACcCpmnGT0u99QE+lLxhAyujiEDExgAoJ1C 8GpR/1FBwfHvO0u0P0G7tK2d =JqYc -----END PGP SIGNATURE-----
This is fantastic patch. Thank you very much. (For "rookies" (such as myself), to apply the patch you will need "patch", which is not included in the boxed RedHat 7.1 distribution. I got patch-2.5.4-9.i386.rpm from ftp.rpmfind.net.) Regards Tielman J de Villiers BondNet Pty Ltd -----Original Message----- From: Greg Sabino Mullane [mailto:greg@turnstep.com] Sent: Wednesday, November 28, 2001 5:52 PM To: pgsql-general@postgresql.org Subject: Re: [GENERAL] Timing a query -----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 > this looks superb. > > one small question though; how do i apply the patch ? I'll assume you have the sources for 7.1.3. I'll rewrite the patch for 7.2b3 in a little bit. Change to the top level of the postgresql source tree. > cd postgresql-7.1.3 Save the file at http://www.gtsm.com/postgres/microtiming.patch to a local file, perhaps named "microtiming.patch" > wget http://www.gtsm.com/postgres/microtiming.patch Patch the source with the file: > patch -bp0 < microtiming.patch If all goes well, you should see: patching file ./src/bin/psql/command.c patching file ./src/bin/psql/common.c patching file ./src/bin/psql/help.c patching file ./src/bin/psql/print.h patching file ./src/bin/psql/startup.c patching file ./src/bin/psql/tab-complete.c patching file ./doc/src/sgml/ref/psql-ref.sgml You can then run make from the top-level directory, or to avoid some output, cd to src/bin/psql and run make from there: >cd src/bin/psql; make When finished, you'll have a new psql binary in the src/bin/psql directory, which should have the microtiming stuff. Test it out before copying it over to anywhere permanent: >./psql template1=# select version(); version - - -------------------------------------------------------------- PostgreSQL 7.1.3 on i686-pc-linux-gnu, compiled by GCC 3.0.1 (1 row) template1=# \m Microsecond timing is on. template1=# select version(); version - - -------------------------------------------------------------- PostgreSQL 7.1.3 on i686-pc-linux-gnu, compiled by GCC 3.0.1 (1 row) TOTAL TIME: 0.001660 template1=# Greg Sabino Mullane greg@turnstep.com PGP Key: 0x14964AC8 200111281041 -----BEGIN PGP SIGNATURE----- Comment: http://www.turnstep.com/pgp.html iQA/AwUBPAUIGrybkGcUlkrIEQK8BACcCpmnGT0u99QE+lLxhAyujiEDExgAoJ1C 8GpR/1FBwfHvO0u0P0G7tK2d =JqYc -----END PGP SIGNATURE----- ---------------------------(end of broadcast)--------------------------- TIP 2: you can get off all lists at once with the unregister command (send "unregister YourEmailAddressHere" to majordomo@postgresql.org)
On Tue, 27 Nov 2001, Tom Lane wrote:
> You can get more info than you probably want by setting show_query_stats
> to true (either with SET, or in postgresql.conf if you want it across
> all backends). Also set debug_print_query to true. Now you'll get
> stuff like this in the postmaster log:
>
> DEBUG: query: select count(*) from tenk1 a, tenk1 b where a.unique1=b.unique2;
> DEBUG: QUERY STATISTICS
Is this available on 7.1.3?
I did:
drf=# set show_query_stats = TRUE;
drf=# set debug_print_query = TRUE;
drf=# select horse,fd from horses limit 1;
horse | fd
-------------------+----
a big kahuna* | d
drf=# show debug_print_query;
NOTICE: debug_print_query is on
drf=# show show_query_stats;
NOTICE: show_query_stats is on
The variables were on, yet I didn't get the debug output.
Francisco Reyes <lists@natserv.com> writes:
> The variables were on, yet I didn't get the debug output.
Did you look in the postmaster log? The stats are not sent to the client.
I think in 7.1 and before, those stats are printed directly to
postmaster stderr, which means you can't log them using syslog either;
you really have to send stderr to someplace useful. In 7.2 the stats
can be logged to syslog ... but they still don't go to the client.
regards, tom lane
On Wed, 28 Nov 2001, Greg Sabino Mullane wrote: > I'll assume you have the sources for 7.1.3. I'll rewrite the > patch for 7.2b3 in a little bit. > > Change to the top level of the postgresql source tree. > > > cd postgresql-7.1.3 > > Save the file at > http://www.gtsm.com/postgres/microtiming.patch > to a local file, perhaps named "microtiming.patch" Why not get this to be included with the main distribution?
I think we have this in the queue for 7.3:
http://216.55.132.35/cgi-bin/pgpatches2
---------------------------------------------------------------------------
> On Wed, 28 Nov 2001, Greg Sabino Mullane wrote:
>
> > I'll assume you have the sources for 7.1.3. I'll rewrite the
> > patch for 7.2b3 in a little bit.
> >
> > Change to the top level of the postgresql source tree.
> >
> > > cd postgresql-7.1.3
> >
> > Save the file at
> > http://www.gtsm.com/postgres/microtiming.patch
> > to a local file, perhaps named "microtiming.patch"
>
> Why not get this to be included with the main distribution?
>
>
> ---------------------------(end of broadcast)---------------------------
> TIP 5: Have you checked our extensive FAQ?
>
> http://www.postgresql.org/users-lounge/docs/faq.html
>
--
Bruce Momjian | http://candle.pha.pa.us
pgman@candle.pha.pa.us | (610) 853-3000
+ If your life is a hard drive, | 830 Blythe Avenue
+ Christ can be your backup. | Drexel Hill, Pennsylvania 19026