Re: SQL logging (log_min_duration_statement) not working

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:smarlowe@g2switchworks.com]
>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
>
>
>