Adding getrusage profiling data to EXPLAIN output - Mailing list pgsql-hackers

From Greg Stark
Subject Adding getrusage profiling data to EXPLAIN output
Date
Msg-id AANLkTimOkx8fOcBsdhZnMHKKfT7=g-WRiuvoQwbYe-4f@mail.gmail.com
Whole thread Raw
Responses Re: Adding getrusage profiling data to EXPLAIN output
List 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

pgsql-hackers by date:

Previous
From: Greg Stark
Date:
Subject: Re: O_DSYNC broken on MacOS X?
Next
From: Josh Berkus
Date:
Subject: Re: recovery.conf location