Thread: Explain analyze time overhead
Hello guys,
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.
I have tried this for several queries, where I need to optimize; and using explain analyze leads alway to a huge time overhead in factor of 10.
This is a little bit starnge for me; did any one experience somthing like this? Can I trust the generated plans?
Regards
On 05-12-13 15:09, salah jubeh wrote:
Hello guys,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.I have tried this for several queries, where I need to optimize; and using explain analyze leads alway to a huge time overhead in factor of 10.This is a little bit starnge for me; did any one experience somthing like this? Can I trust the generated plans?Regards
Explain analyze does a lot more work than just explaining the query, it excecutes it and takes not of how long things actually took, which itself takes time. Apparently on some machines, it can take much longer than just executing the query would take.
From the manual:
"In order to measure the run-time cost of each node in the execution plan, the current implementation of EXPLAIN ANALYZE adds profiling overhead to query execution. As a result, running EXPLAIN ANALYZE on a query can sometimes take significantly longer than executing the query normally. The amount of overhead depends on the nature of the query, as well as the platform being used. The worst case occurs for plan nodes that in themselves require very little time per execution, and on machines that have relatively slow operating system calls for obtaining the time of day."
salah jubeh <s_jubeh@yahoo.com> writes:
> When I excute a query,� the exection time is about 1 minute; however, when I execute the query with explain analyze
theexcution 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.
regards, tom lane
Hello Tom,
The hardware is pretty good, I have 8 cpus of Intel(R) Core(TM) i7, 2.4 GH , and 16 Gib of RAM. Is there any configuration parameter that can lead to this issue.
Regards
Explain analyze does a lot more work than just explaining the query, it excecutes it and takes not of how long things actually took, which itself takes time. Apparently on some machines, it can take much longer than just executing the query would take.
From the manual:
The hardware is pretty good, I have 8 cpus of Intel(R) Core(TM) i7, 2.4 GH , and 16 Gib of RAM. Is there any configuration parameter that can lead to this issue.
Regards
On Thursday, December 5, 2013 3:23 PM, vincent elschot <vinny@xs4all.nl> wrote:
On 05-12-13 15:09, salah jubeh wrote:
Hello guys,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.I have tried this for several queries, where I need to optimize; and using explain analyze leads alway to a huge time overhead in factor of 10.This is a little bit starnge for me; did any one experience somthing like this? Can I trust the generated plans?Regards
Explain analyze does a lot more work than just explaining the query, it excecutes it and takes not of how long things actually took, which itself takes time. Apparently on some machines, it can take much longer than just executing the query would take.
From the manual:
"In order to measure the run-time cost of each node in the execution plan, the current implementation of EXPLAIN ANALYZE adds profiling overhead to query execution. As a result, running EXPLAIN ANALYZE on a query can sometimes take significantly longer than executing the query normally. The amount of overhead depends on the nature of the query, as well as the platform being used. The worst case occurs for plan nodes that in themselves require very little time per execution, and on machines that have relatively slow operating system calls for obtaining the time of day."
salah jubeh <s_jubeh@yahoo.com> wrote: > The hardware is pretty good, I have 8 cpus of Intel(R) Core(TM) > i7, 2.4 GH , and 16 Gib of RAM. Is there any configuration > parameter that can lead to this issue. What OS? -- Kevin Grittner EDB: http://www.enterprisedb.com The Enterprise PostgreSQL Company
On Thu, Dec 5, 2013 at 09:22:14AM -0500, Tom Lane wrote:
> salah jubeh <s_jubeh@yahoo.com> writes:
> > When I excute a query,� the exection time is about 1 minute; however, when I execute the query with explain analyze
theexcution 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@momjian.us> http://momjian.us
EnterpriseDB http://enterprisedb.com
+ Everyone has their own god. +
>>>On Thu, Dec 5, 2013 at 09:22:14AM -0500, Tom Lane wrote:
>>> salah jubeh <s_jubeh@yahoo.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
--
>>> salah jubeh <s_jubeh@yahoo.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@momjian.us> wrote:
On Thu, Dec 5, 2013 at 09:22:14AM -0500, Tom Lane wrote:
> salah jubeh <s_jubeh@yahoo.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@momjian.us> http://momjian.us
EnterpriseDB http://enterprisedb.com
+ Everyone has their own god. +
--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
> salah jubeh <s_jubeh@yahoo.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@momjian.us> http://momjian.us
EnterpriseDB http://enterprisedb.com
+ Everyone has their own god. +
--
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
On Tue, Dec 10, 2013 at 01:53:54PM -0800, salah jubeh wrote: > 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. The executable is not tied to any particular Postgres version, so you could get the 9.3 binary and just use that. -- Bruce Momjian <bruce@momjian.us> http://momjian.us EnterpriseDB http://enterprisedb.com + Everyone has their own god. +