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)