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

From Greg Stark
Subject Re: Adding getrusage profiling data to EXPLAIN output
Date
Msg-id AANLkTikWGw5EZzJYq_NR+UpLpjy7Yp+h-Xof4AUwZvkQ@mail.gmail.com
Whole thread Raw
In response to Re: Adding getrusage profiling data to EXPLAIN output  (Itagaki Takahiro <itagaki.takahiro@gmail.com>)
Responses Re: Adding getrusage profiling data to EXPLAIN output
List pgsql-hackers
On Thu, Sep 30, 2010 at 6:51 PM, Itagaki Takahiro
<itagaki.takahiro@gmail.com> wrote:
> How much overhead do you have with "resource" option?
> getrusage() calls for each tuple might have considerable overheads.
> How much difference between (analyze) and (analyze, resource) options?

Here's strace -c for a select count(*) from x where x is a table with
800,000 narrow rows entirely in shared buffers.

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------99.56    0.025299           0   6400024
getrusage0.44    0.000112           0      9872           read 0.00    0.000000           0         1           open
0.00   0.000000           0        13           lseek 0.00    0.000000           0        10           sendto 0.00
0.000000          0         5           recvfrom 
------ ----------- ----------- --------- --------- ----------------
100.00    0.025411               6409925           total

That's under 40ns per getrusage call. My test C program seems to take
about 300ns per getrusage call however so I'm not sure I trust the
strace results. Either way that's pretty negligable. It's basically
just copying a struct from kernel space to user space.

Of course it depends on what query you run. In my very simple example
of doing select count(*) from x where x has 800k rows the whole query
takes about 100ms. Since there are two nodes (the seq scan and the
aggregate) it has to do 3.2 million getrusage calls. That's about
960ms total. So it imposes nearly a 10x speed slowdown but only
because the base measurement was so low. For what it's worth that's
less than the overhead from gettimeofday which seems to be imposing
about a 1100ms of overhead.

The observed timings are
query only                         100.5ms
explain (analyze)              1234.9ms
explain (analyze,resource) 2210.2ms

--
greg


pgsql-hackers by date:

Previous
From: Robert Haas
Date:
Subject: Re: So git pull is shorthand for what exactly?
Next
From: Peter Eisentraut
Date:
Subject: Re: PG-Git usernames