Thread: SQL logging (log_min_duration_statement) not working properly
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.
Thanks!
Pallav
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?
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)
Pallav Kalva <pkalva@deg.cc> writes:
> 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 .
Did you set log_min_duration_statement in a way that would actually
affect Hibernate (ie, change postgresql.conf and sighup the postmaster)?
regards, tom lane
Tom Lane wrote: >Pallav Kalva <pkalva@deg.cc> writes: > > >> 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 . >> >> > >Did you set log_min_duration_statement in a way that would actually >affect Hibernate (ie, change postgresql.conf and sighup the postmaster)? > > regards, tom lane > > > I changed the log_min_duration_statement from 60000 to 5000 and then ran --> pg_ctl reload -D <data cluster location> and then i ran the queries from hibernate. These are the only things which I did on the postgres side.
Pallav Kalva <pkalva@deg.cc> writes:
>>> 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 .
Theory B is that Hibernate is a Java program and is using a recent
version of the JDBC driver. JDBC now uses Parse/Bind/Execute messages
instead of the old-style protocol, and we haven't put support for
log_min_duration_statement into that code path yet ...
regards, tom lane
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.
Scott Marlowe wrote: >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? > Postgres is logging everything else , even the queries which take more than 5 sec which are executed from psql not the Hibernate queries. The main concern for me was to check if the bad queries which are executed from Hibernate are logged or not. > >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 > > >