Re: [ADMIN] SQL logging (log_min_duration_statement) not working

[Pallav Kalva]

Hi Anjan,
   I used to follow this procedure while using Postgres 7.4 version, we 
are now using Postgres 8.0.2 and I dont have give the log file path name 
everytime I start the postgres , I use these paramaters in the 
postgresql.conf

redirect_stderr = true     
log_directory = '/var/lib/pgsql8/pg_log'  
log_filename = 'postgresql-%a.log'

Pallav
Anjan Dave wrote:
For logging the queries taking 5+ seconds, try this:
In postgresql.conf:
syslog = 0    # range 0-2; 0=stdout; 1=both; 2=syslog
syslog_facility = 'LOCAL0'
syslog_ident = 'postgres'
log_min_duration_statement = 5000
Then, in your pg startup script (etc/init.d/Postgresql), you want to
have something like PGLOG variable...and change the startup command so
stuff goes into this file:
PGLOG=/var/log/pglogs
export PGLOG
 $SU -l postgres -c "$PGENGINE/initdb --pgdata=$PGDATA" >> $PGLOG 2>&1
< /dev/null
$SU -l postgres -c "$PGENGINE/postmaster -p ${PGPORT} -D '${PGDATA}'
${PGOPTS} &" >> $PGLOG 2>&1 < /dev/null
Note, you need to stop|start the database for all this, and do copy your
original init.d/Postgresql and the data/Postgresql.conf files first.
Thanks,
Anjan
-----Original Message-----
From: Scott Marlowe [mailto:[EMAIL PROTECTED] 
Sent: Wednesday, May 18, 2005 11:52 AM
To: Pallav Kalva
Cc: pgsql-admin@postgresql.org
Subject: Re: [ADMIN] SQL logging (log_min_duration_statement) not
working

On Wed, 2005-05-18 at 09:49, Pallav Kalva wrote:
 

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 :
   

SNIP
 

  ->  Nested Loop  (cost=0.00..17503496.52 rows=678 width=4) (actual 
time=5.185..31575.629 rows=398459 loops=1)
   

SNIP
 

Total runtime: 38026.606 ms
(13 rows)
   

OK, two problems here, I assume.  One is your logging is dodgy right
now.  Is postgresql logging anything else?  Are you sure your logs are
going where you think they are, etc?
Secondly, it looks from the nested loop part of your explain analyze
that there's a part where the query planner THINKS there's gonna be 678
rows, but actually gets 398459, that's a miscalculation by a factor of
about 600.  Since there's no functions or anything I recognize as being
a common cause of such a mis-estimation, I'd guess that either you need
to analyze, or if you have analyzed, you may need to alter the stats
target for the column entrydate.
---------------------------(end of broadcast)---------------------------
TIP 6: Have you searched our list archives?
              http://archives.postgresql.org
---------------------------(end of broadcast)---------------------------
TIP 5: Have you checked our extensive FAQ?
              http://www.postgresql.org/docs/faq
 


---------------------------(end of broadcast)---------------------------
TIP 7: don't forget to increase your free space map settings