Postgres Pro
Downloads
Home   >   mailing lists

Thread: Strange query duration

Strange query duration

From
"Fernando Hevia"
Date:
Hi list,
I just enabled log duration in a 8.3.1 database and got puzzling
information.
I have a daemon shell-script run every 10 seconds the following:  psql -c "select f_tasador();"
The 'f_tasador' procedure is quite fast. As per log output I can see the
procedure completes its execution within one second. Nevertheless in the LOG
duration entry it shows a statement duration of over 36 secs.
¿What is going on? ¿Where come those 36 seconds from?

Regards,
Fernando


--- Postgres Log extract ---
2008-07-22 15:52:37 ART|postgres| LOG:  statement: select f_tasador();
2008-07-22 15:52:37 ART|postgres| NOTICE:  [3576450000] Billable account
found
2008-07-22 15:52:37 ART|postgres| NOTICE:  [3576450000] Destination
3514601344 not billable
2008-07-22 15:52:37 ART|postgres| NOTICE:  [3576450000] Destination
3514719096 not billable
2008-07-22 15:52:37 ART|postgres| NOTICE:  [3576450000] Destination
3576421309 not billable
2008-07-22 15:52:37 ART|postgres| NOTICE:  [3576450000] Destination
3514601344 not billable
2008-07-22 15:52:37 ART|postgres| NOTICE:  [3576450000] Destination
3514601344 not billable
2008-07-22 15:52:37 ART|postgres| NOTICE:  [3576450000] Destination
3514601344 not billable
2008-07-22 15:52:37 ART|postgres| NOTICE:  [3576450002] No active billable
account found
2008-07-22 15:52:37 ART|postgres| NOTICE:  [3576450008] Billable account
found
2008-07-22 15:52:37 ART|postgres| NOTICE:  [3576450008] Destination
3514601344 not billable
2008-07-22 15:52:37 ART|postgres| NOTICE:  [3576450008] Destination
3514601344 not billable
2008-07-22 15:52:37 ART|postgres| NOTICE:  [3576450008] Destination
3514601344 not billable
2008-07-22 15:52:37 ART|postgres| NOTICE:  [3576450008] Destination
3514601344 not billable
2008-07-22 15:52:37 ART|postgres| NOTICE:  [3576450008] Destination
3514601344 not billable
2008-07-22 15:52:37 ART|postgres| NOTICE:  [3576450008] Destination
3514601344 not billable
2008-07-22 15:52:37 ART|postgres| NOTICE:  [3576450009] Billable account
found
2008-07-22 15:52:37 ART|postgres| NOTICE:  [3576450009] Destination
3516009059 not billable
2008-07-22 15:52:37 ART|postgres| LOG:  duration: 38.154 ms
2008-07-22 15:52:47 ART|postgres| LOG:  statement: select f_tasador();
2008-07-22 15:52:47 ART|postgres| NOTICE:  [3576450000] Billable account
found
2008-07-22 15:52:47 ART|postgres| NOTICE:  [3576450000] Destination
3514601344 not billable
2008-07-22 15:52:47 ART|postgres| NOTICE:  [3576450000] Destination
3514719096 not billable
2008-07-22 15:52:47 ART|postgres| NOTICE:  [3576450000] Destination
3576421309 not billable
2008-07-22 15:52:47 ART|postgres| NOTICE:  [3576450000] Destination
3514601344 not billable
2008-07-22 15:52:47 ART|postgres| NOTICE:  [3576450000] Destination
3514601344 not billable
2008-07-22 15:52:47 ART|postgres| NOTICE:  [3576450000] Destination
3514601344 not billable
2008-07-22 15:52:47 ART|postgres| NOTICE:  [3576450002] No active billable
account found
2008-07-22 15:52:47 ART|postgres| NOTICE:  [3576450008] Billable account
found
2008-07-22 15:52:47 ART|postgres| NOTICE:  [3576450008] Destination
3514601344 not billable
2008-07-22 15:52:47 ART|postgres| NOTICE:  [3576450008] Destination
3514601344 not billable
2008-07-22 15:52:47 ART|postgres| NOTICE:  [3576450008] Destination
3514601344 not billable
2008-07-22 15:52:47 ART|postgres| NOTICE:  [3576450008] Destination
3514601344 not billable
2008-07-22 15:52:47 ART|postgres| NOTICE:  [3576450008] Destination
3514601344 not billable
2008-07-22 15:52:47 ART|postgres| NOTICE:  [3576450008] Destination
3514601344 not billable
2008-07-22 15:52:47 ART|postgres| NOTICE:  [3576450009] Billable account
found
2008-07-22 15:52:47 ART|postgres| NOTICE:  [3576450009] Destination
3516009059 not billable
2008-07-22 15:52:47 ART|postgres| LOG:  duration: 36.781 ms

Re: Strange query duration

From
Stephan Szabo
Date:
On Tue, 22 Jul 2008, Fernando Hevia wrote:

> I just enabled log duration in a 8.3.1 database and got puzzling
> information.
> I have a daemon shell-script run every 10 seconds the following:
>
>    psql -c "select f_tasador();"
>
> The 'f_tasador' procedure is quite fast. As per log output I can see the
> procedure completes its execution within one second. Nevertheless in the LOG
> duration entry it shows a statement duration of over 36 secs.

I think you're misleading the log. It's showing a number of milliseconds
(ms) not seconds.

> 2008-07-22 15:52:37 ART|postgres| LOG:  statement: select f_tasador();
> 2008-07-22 15:52:37 ART|postgres| LOG:  duration: 38.154 ms
> 2008-07-22 15:52:47 ART|postgres| LOG:  statement: select f_tasador();
> 2008-07-22 15:52:47 ART|postgres| LOG:  duration: 36.781 ms

Re: Strange query duration

From
"Richard Broersma"
Date:
On Tue, Jul 22, 2008 at 12:10 PM, Fernando Hevia <fhevia@ip-tel.com.ar> wrote:

>Nevertheless in the LOG
> duration entry it shows a statement duration of over 36 secs.
> ¿What is going on? ¿Where come those 36 seconds from?

> 2008-07-22 15:52:37 ART|postgres| LOG:  duration: 38.154 ms

:o) You might be encountering a bit of parallax. This shows both 38
and 36 *milliseconds*.


--
Regards,
Richard Broersma Jr.

Visit the Los Angles PostgreSQL Users Group (LAPUG)
http://pugs.postgresql.org/lapug

Re: Strange query duration

From
"Fernando Hevia"
Date:

> De: Richard Broersma [mailto:richard.broersma@gmail.com] 
> Enviado el: Martes, 22 de Julio de 2008 17:19
> 
> > 2008-07-22 15:52:37 ART|postgres| LOG:  duration: 38.154 ms
> 
> :o) You might be encountering a bit of parallax. This shows 
> both 38 and 36 *milliseconds*.
> 

That's embarrasing... I mistook the decimal punctuation symbol (in my native
Spanish it's the coma)
Good to know it performs as fast as expected though. :)

Thanks.

Re: Strange query duration

From
Tom Lane
Date:
"Fernando Hevia" <fhevia@ip-tel.com.ar> writes:
> The 'f_tasador' procedure is quite fast. As per log output I can see the
> procedure completes its execution within one second. Nevertheless in the LOG
> duration entry it shows a statement duration of over 36 secs.

It says milliseconds, not seconds.
        regards, tom lane