Re: Explain analyze time overhead

>>>On Thu, Dec  5, 2013 at 09:22:14AM -0500, Tom Lane wrote:
>>> salah jubeh <s_jubeh(at)yahoo(dot)com> writes:
>>> When I excute a query,�the exection time is about 1 minute;
however, when I execute the query with explain analyze the excution time
jumps to 10 minutes.
>>
>> This isn't exactly unheard of, although it sounds like you have a
>> particularly bad case.  Cheap commodity PCs tend to have clock hardware
>> that takes multiple microseconds to read ... which was fine thirty years
>> ago when that hardware design was set, but with modern CPUs that's
>> painfully slow.
>>
>> Short of getting a better machine, you might look into whether you can run
>> a 64-bit instead of 32-bit operating system.  In some cases that allows
>> a clock reading to happen without a context switch to the kernel.
>>
>> > This is a little bit starnge for me; did any one experience somthing like this? Can I trust the generated plans?
>>
>> The numbers are fine as far as they go, but you should realize that the
>> relative cost of the cheaper plan nodes is being overstated, since the
>> added instrumentation cost is the
same per node call regardless of how
>> much work happens within the node.

>The original poster might also want to run pg_test_timing to get
>hardware timing overhead:
>   http://www.postgresql.org/docs/9.3/static/pgtesttiming.html

Thanks for the link, I find it very useful,  unfortunatly I am using 9.1.11 version.

After digging a little bit, I find out that the gettimeofday is indeed a little bit slower on this particular machine than other machines, but it is not that significanat difference. The query I am running is not optimized, and for some  reason the material operator is the one which causes most of the overhead. The whole issue is due to cross colums statistics and highly correlated predicates, the number of estimated records are much less than the actual number.  Still, I did not understand completly, why the material operator consume about 9 minutes when I run explain analyze. i.e how many times we call gettimeofday for the material operator -I need to calculate this-? Finally, for testing purposes, I have disabled material  and the query execution time dropped from 1 minute to 12 second.

Regards
--

On Tuesday, December 10, 2013 9:42 PM, Bruce Momjian <bruce(at)momjian(dot)us> wrote:

On Thu, Dec  5, 2013 at 09:22:14AM -0500, Tom Lane wrote:
> salah jubeh <s_jubeh(at)yahoo(dot)com> writes:
> > When I excute a query,�the exection time is about 1 minute; however, when I execute the query with explain analyze the excution time jumps to 10 minutes.
>
> This isn't exactly unheard of, although it sounds like you have a
> particularly bad case.  Cheap commodity PCs tend to have clock hardware
> that takes multiple microseconds to read ... which was fine thirty years
> ago when that hardware design was set, but with modern CPUs that's
> painfully slow.
>
> Short of getting a better machine, you might look into whether you can run
> a 64-bit instead of 32-bit operating system.  In some cases that allows
> a clock reading
to happen without a context switch to the kernel.
>
> > This is a little bit starnge for me; did any one experience somthing like this? Can I trust the generated plans?
>
> The numbers are fine as far as they go, but you should realize that the
> relative cost of the cheaper plan nodes is being overstated, since the
> added instrumentation cost is the same per node call regardless of how
> much work happens within the node.

The original poster might also want to run pg_test_timing to get
hardware timing overhead:

    http://www.postgresql.org/docs/9.3/static/pgtesttiming.html

--
  Bruce Momjian  <bruce(at)momjian(dot)us>        http://momjian.us
  EnterpriseDB                            http://enterprisedb.com

  + Everyone has their own god. +