Thread: Logging long queries: not all get logged

Logging long queries: not all get logged

From
Date:
Hi,

I'm running PG 8.0.3.  I'm trying to catch slow queries, so I have this in postgresql.conf:

  # log queries that take more than 500 ms
  log_min_duration_statement = 500       # in ms

This does log _some_ queries that take > 500 ms to run.
However, it looks like not all queries get logged!

And I think I spotted a pattern:

Queries that DO get logged are:
  - queries run using psql
  - queries run by the java app that uses JDBC to talk to my PG database

Queries that do NOT get logged are:
  - queries run by the java app that uses Hibernate to talk to my PG database

If this is not the right place to ask about this (because there is java/Hibernate in the game), please let me know
whereI should ask. 

However, as far as I know, all of the above queries end up hitting the PG server the same way.  In other words, the PG
servershould see all these queries the same way -- there is no distinction between psql, JDBC, and Hibernate queries
fromthe point of view of PG server, so it's really bizzare that not all slow queries get logged. 

Has anyone seen this behaviour before?
Are there logging fixes in PG 8.1.3 that might address this issue?

Thanks,
Otis




Re: Logging long queries: not all get logged

From
Simon Riggs
Date:
On Wed, 2006-05-10 at 09:34 -0700, ogjunk-pgjedan@yahoo.com wrote:

> Has anyone seen this behaviour before?
> Are there logging fixes in PG 8.1.3 that might address this issue?

Yes and Yes.

But good detective work.

Sounds like it needs adding to the 8.0 docs...or would you like to put a
comment on the appropriate page of the annotated docs?

--
  Simon Riggs
  EnterpriseDB          http://www.enterprisedb.com


Re: Logging long queries: not all get logged

From
Chris Browne
Date:
ogjunk-pgjedan@yahoo.com writes:
> Hi,
>
> I'm running PG 8.0.3.  I'm trying to catch slow queries, so I have this in postgresql.conf:
>
>   # log queries that take more than 500 ms
>   log_min_duration_statement = 500       # in ms
>
> This does log _some_ queries that take > 500 ms to run.
> However, it looks like not all queries get logged!
>
> And I think I spotted a pattern:
>
> Queries that DO get logged are:
>   - queries run using psql
>   - queries run by the java app that uses JDBC to talk to my PG database
>
> Queries that do NOT get logged are:
>   - queries run by the java app that uses Hibernate to talk to my PG database

We occasionally have run into seemingly the same issue.

Question:

Are you certain that the queries are taking longer than 500ms for
PostgreSQL to process them?

Or are you merely certain that Hibernate is reporting that it took
longer than that for *it* to process them?

We have had Java applications which would report spurious "slow"
queries any time the garbage collector had to do any significant
amount of work.

It could be that the garbage collector is causing Hibernate to stall
while processing its logging, thereby incorrectly reporting that
database queries are running slow...
--
(reverse (concatenate 'string "gro.gultn" "@" "enworbbc"))
http://cbbrowne.com/info/finances.html
The only problem
with Haiku is that you just
get started and then

Re: Logging long queries: not all get logged

From
Date:
Hi Chris,

I'm pretty sure (I do no timing on the Hibernate/java/app side).  I changed the config to:

# log queries that take more than 1 ms
log_min_duration_statement = 1       # in ms

Still nothing in the log :) (I did ctl_reload the postmaster)

Simon Riggs confirmed this is a known bug in another email, and 8.1.* should contain a fix.  Good excuse to move to
8.0*.
Or does anyone know if 8.2 is around the corner? (coming in days or a few weeks?)

Thanks,
Otis


----- Original Message ----
From: Chris Browne <cbbrowne@acm.org>
To: pgsql-admin@postgresql.org
Sent: Wednesday, May 10, 2006 3:28:02 PM
Subject: Re: [ADMIN] Logging long queries: not all get logged

ogjunk-pgjedan@yahoo.com writes:
> Hi,
>
> I'm running PG 8.0.3.  I'm trying to catch slow queries, so I have this in postgresql.conf:
>
>   # log queries that take more than 500 ms
>   log_min_duration_statement = 500       # in ms
>
> This does log _some_ queries that take > 500 ms to run.
> However, it looks like not all queries get logged!
>
> And I think I spotted a pattern:
>
> Queries that DO get logged are:
>   - queries run using psql
>   - queries run by the java app that uses JDBC to talk to my PG database
>
> Queries that do NOT get logged are:
>   - queries run by the java app that uses Hibernate to talk to my PG database

We occasionally have run into seemingly the same issue.

Question:

Are you certain that the queries are taking longer than 500ms for
PostgreSQL to process them?

Or are you merely certain that Hibernate is reporting that it took
longer than that for *it* to process them?

We have had Java applications which would report spurious "slow"
queries any time the garbage collector had to do any significant
amount of work.

It could be that the garbage collector is causing Hibernate to stall
while processing its logging, thereby incorrectly reporting that
database queries are running slow...
--
(reverse (concatenate 'string "gro.gultn" "@" "enworbbc"))
http://cbbrowne.com/info/finances.html
The only problem
with Haiku is that you just
get started and then

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