Skip site navigation (1) Skip section navigation (2)

Re: SQL logging (log_min_duration_statement) not working

From: Pallav Kalva <pkalva(at)deg(dot)cc>
To: Scott Marlowe <smarlowe(at)g2switchworks(dot)com>
Cc: pgsql-admin(at)postgresql(dot)org
Subject: Re: SQL logging (log_min_duration_statement) not working
Date: 2005-05-18 14:49:31
Message-ID: 428B55FB.3030805@deg.cc (view raw or flat)
Thread:
Lists: pgsql-admin
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)


In response to

Responses

pgsql-admin by date

Next:From: Tom LaneDate: 2005-05-18 15:18:08
Subject: Re: SQL logging (log_min_duration_statement) not working properly
Previous:From: Scott MarloweDate: 2005-05-18 14:42:07
Subject: Re: database A to database B

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group