Re: Adding getrusage profiling data to EXPLAIN output

On Thu, Sep 30, 2010 at 6:51 PM, Itagaki Takahiro
<itagaki(dot)takahiro(at)gmail(dot)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 getrusage
0.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