total execution time as reported by auto_explain

Lists: pgsql-hackers
From: Jaime Casanova <jcasanov(at)systemguards(dot)com(dot)ec>
To: PostgreSQL-development <pgsql-hackers(at)postgresql(dot)org>
Subject: total execution time as reported by auto_explain
Date: 2009-11-11 06:08:28
Message-ID: 3073cc9b0911102208q76afb447k4ffae74b3df80c24@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-hackers

Hi,

I was using auto_explain to log plans (with analyze option on) from
queries that take more than 500ms, something i found i little odd is
that the duration says 779ms but actual time says 269ms (almost 3
times lower), maybe some kind of instrumentation cleanup can explain
this?

2009-11-10 10:32:41 GMTLOG: duration: 779.938 ms plan:
Sort (cost=1943.99..1967.38 rows=9355 width=466) (actual
time=235.655..269.061 rows=4997 loops=1)

--
Atentamente,
Jaime Casanova
Soporte y capacitación de PostgreSQL
Asesoría y desarrollo de sistemas
Guayaquil - Ecuador
Cel. +59387171157

Attachment Content-Type Size
explain_no_entendible.txt text/plain 1.5 KB
From: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
To: Jaime Casanova <jcasanov(at)systemguards(dot)com(dot)ec>
Cc: PostgreSQL-development <pgsql-hackers(at)postgresql(dot)org>
Subject: Re: total execution time as reported by auto_explain
Date: 2009-11-11 14:47:30
Message-ID: 5609.1257950850@sss.pgh.pa.us
Views: Raw Message | Whole Thread | Download mbox | Resend email
Lists: pgsql-hackers

Jaime Casanova <jcasanov(at)systemguards(dot)com(dot)ec> writes:
> I was using auto_explain to log plans (with analyze option on) from
> queries that take more than 500ms, something i found i little odd is
> that the duration says 779ms but actual time says 269ms (almost 3
> times lower), maybe some kind of instrumentation cleanup can explain
> this?

Client slow about absorbing the rows, perhaps? The actual data output
process isn't counted as part of the plan tree's runtime ... but it
would be included in the total elapsed time.

regards, tom lane