| 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 | 
| Views: | Whole Thread | Raw Message | Download mbox | Resend email | 
| 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 | Content-Type | Size | 
|---|---|---|
| explain-getrusage.diff | text/x-patch | 13.1 KB | 
| From | Date | Subject | |
|---|---|---|---|
| Next Message | Josh Berkus | 2010-10-01 00:21:36 | Re: recovery.conf location | 
| Previous Message | Greg Stark | 2010-09-30 22:07:09 | Re: O_DSYNC broken on MacOS X? |