Re: SQL logging (log_min_duration_statement) not working

Scott Marlowe wrote:

>On Wed, 2005-05-18 at 08:35, Pallav Kalva wrote:
>
>
>>Hi Everybody,
>>
>>
>> I am having problems with logging long running SQL in the log file.
>>I have set log_min_duration_statement = 5000 (5secs) and it is not
>>logging sql statements that took over 5 secs and this is only from
>>queries generated by Hibernate . here is a sample query from hibernate :
>>
>>-----------------------------------------------------------------------------------------
>>select listingadd1_.addressid as col_0_0_
>>from listing.listing listing0_, listing.address listingadd1_
>>where ((select count(taxrolls2_.fkaddressid)
>> from listing.taxroll taxrolls2_
>> where listingadd1_.addressid=taxrolls2_.fkaddressid)=0 )
>> and(listing0_.fkbestaddressid=listingadd1_.addressid )
>> and(listing0_.entrydate>$1 )
>>order by listingadd1_.addressid asc
>>--------------------------------------------------------------------------------------------
>>
>> This above query take more than 5 secs to run and it wont get logged ,
>>where as all other queries which are not generated by Hibernate are
>>logged. Is this expected behavior ? am I missing something else ?
>>Please advice.
>>
>>
>
>Are you sure it's taking more than 5 seconds to run, not that it's
>taking <5 seconds to run and >5 seconds to return the data. I'm pretty
>sure the time it takes to ship out the data isn't counted in the time
>used to decide whether to log the query or not by the postmaster.
>
>I.e. what does explain analyze QUERY HERE say about the execution time?
>
>
>
Hi Scott,

Thanks! for the reply. The query for sure runs for more than 5
secs, I passed the same value again and ran the query in the psql with
explain analyze .

Here is the explain analyze output :

explain analyze
select listingadd1_.addressid as col_0_0_
from listing.listing listing0_, listing.address listingadd1_
where ((select count(taxrolls2_.fkaddressid)
from listing.taxroll taxrolls2_
where listingadd1_.addressid=taxrolls2_.fkaddressid)=0 )
and(listing0_.fkbestaddressid=listingadd1_.addressid )
and(listing0_.entrydate>'2004-12-15' )
order by listingadd1_.addressid asc;

QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Sort (cost=17503528.41..17503530.10 rows=678 width=4) (actual
time=37279.353..37750.532 rows=398459 loops=1)
Sort Key: listingadd1_.addressid
-> Nested Loop (cost=0.00..17503496.52 rows=678 width=4) (actual
time=5.185..31575.629 rows=398459 loops=1)
-> Seq Scan on listing listing0_ (cost=0.00..10312.25
rows=135580 width=4) (actual time=4.885..1834.806 rows=406740 loops=1)
Filter: (entrydate > '2004-12-15 00:00:00'::timestamp
without time zone)
-> Index Scan using pk_address_addressid on address
listingadd1_ (cost=0.00..129.01 rows=1 width=4) (actual
time=0.065..0.067 rows=1 loops=406740)
Index Cond: ("outer".fkbestaddressid =
listingadd1_.addressid)
Filter: ((subplan) = 0)
SubPlan
-> Aggregate (cost=123.00..123.00 rows=1 width=4)
(actual time=0.015..0.016 rows=1 loops=406740)
-> Index Scan using idx_taxroll_fkaddressid on
taxroll taxrolls2_ (cost=0.00..122.89 rows=42 width=4) (actual
time=0.009..0.009 rows=0 loops=406740)
Index Cond: ($0 = fkaddressid)
Total runtime: 38026.606 ms
(13 rows)