Skip site navigation (1) Skip section navigation (2)

Adding getrusage profiling data to EXPLAIN output

From: Greg Stark <stark(at)mit(dot)edu>
To: "<pgsql-hackers(at)postgresql(dot)org>" <pgsql-hackers(at)postgresql(dot)org>
Subject: Adding getrusage profiling data to EXPLAIN output
Date: 2010-10-01 00:16:52
Message-ID: AANLkTimOkx8fOcBsdhZnMHKKfT7=g-WRiuvoQwbYe-4f@mail.gmail.com (view raw or flat)
Thread:
Lists: pgsql-hackers
Attached is a patch to display getrusage output to EXPLAIN output.
This is the patch I mentioned previously in
http://archives.postgresql.org/pgsql-hackers/2010-02/msg00684.php and
it raises the same issues we were talking about then. Should the
resource usage stats displayed be per-iteration totals for the whole
query execution for that node. I can't see dividing by nloops making
things clearer but the discrepancy is becoming more noticeable. I
wonder if there's anything we can do to make things clearer.

Incidentally, this is a first cut at the patch written in a single
sitting. I need to go through it again to make sure I didn't do
anything silly. One thing I know is broken is Windows support. I
fleshed out our getrusage stub a bit but I can't test it at all, and
the INSTR_TIME_* macros actually are defined differently on windows so
I can't use them quite so simply on struct timeval. The simplest
option is to define the struct timeval versions always even if
INSTR_TIME_* doesn't use them and this code can use them directly.
Another would be to modify the struct rusage definition on Windows so
we use the native Windows time datatype -- which would be tempting
since it would avoid the loss of precision in "only" having
microsecond precision.


postgres=# explain (analyze,  resource) select * from x;
                                                 QUERY PLAN
-------------------------------------------------------------------------------------------------------------
 Seq Scan on x  (cost=0.00..11540.00 rows=800000 width=4) (actual
time=69.851..1287.025 rows=800000 loops=1)
   Resources: sys=240.000ms user=940.000ms read=27.7MB
 Total runtime: 2431.237 ms
(3 rows)

[...flush buffers and drop caches between tests...]

postgres=# explain (analyze, verbose, buffers, resource) select * from x;
                                                     QUERY PLAN
--------------------------------------------------------------------------------------------------------------------
 Seq Scan on public.x  (cost=0.00..11540.00 rows=800000 width=4)
(actual time=28.739..1290.786 rows=800000 loops=1)
   Output: generate_series
   Resources: sys=280.000ms user=890.000ms read=27.7MB minflt=65
nvcsw=9 nivcsw=633
   Buffers: shared read=3540
 Total runtime: 2487.629 ms
(5 rows)


-- 
greg

Attachment: explain-getrusage.diff
Description: text/x-patch (13.1 KB)

Responses

pgsql-hackers by date

Next:From: Josh BerkusDate: 2010-10-01 00:21:36
Subject: Re: recovery.conf location
Previous:From: Greg StarkDate: 2010-09-30 22:07:09
Subject: Re: O_DSYNC broken on MacOS X?

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group