Thread: phantom long-running query (check_postgres.pl reports a long-running query, but the database logs don't show it)

I got an alert from check_postgres.pl today on a long-running query on
our production database, but our PostgreSQL 8.4.9 server log, which is
configured to log queries over 5 seconds long
("log_min_duration_statement = 5000") does not show the query.

check_postgres.pl showed:
Date/Time: Wed Feb 8 08:41:36 PST 2012
POSTGRES_QUERY_TIME WARNING: (host:xxx) longest query: 264s
(database:xxx PID:xxx port:xxx address:xxx username:xxx)

postgres log showed other long-running queries, but nothing over 48s.

It's really interesting why the database server log does not show this query.

Can you think of some scenario where check_postgres.pl would see a
long-running query but it would not get logged by the database server?

I checked the server log and there is nothing there for 08:41 at all.
08:40 and 08:42, yes, some queries over 5 secs, but nothing even close
to 264 secs.

I've added the verbose switch to my check_postgres.pl script so we'll
have a record of what was the long-running query.

Best,
-at

On Πεμ 09 Φεβ 2012 02:32:37 Aleksey Tsalolikhin wrote:
> I got an alert from check_postgres.pl today on a long-running query on
> our production database, but our PostgreSQL 8.4.9 server log, which is
> configured to log queries over 5 seconds long
> ("log_min_duration_statement = 5000") does not show the query.
>
> check_postgres.pl showed:
> Date/Time: Wed Feb 8 08:41:36 PST 2012
> POSTGRES_QUERY_TIME WARNING: (host:xxx) longest query: 264s
> (database:xxx PID:xxx port:xxx address:xxx username:xxx)
>
> postgres log showed other long-running queries, but nothing over 48s.
>
> It's really interesting why the database server log does not show this
> query.
>
> Can you think of some scenario where check_postgres.pl would see a
> long-running query but it would not get logged by the database server?
>
> I checked the server log and there is nothing there for 08:41 at all.
> 08:40 and 08:42, yes, some queries over 5 secs, but nothing even close
> to 264 secs.
>
> I've added the verbose switch to my check_postgres.pl script so we'll
> have a record of what was the long-running query.
>

You should either look at the source of this perl script to see what it is
doing, or enable log_statement = 'all' in postgresql.conf and send the
postmaster the -HUP signal, and then watch the postgresql log for the queries
that the perl script is issueing. Then replay those queries by hand and
examine them.
Also you can always check pg_stat_activity table.

> Best,
> -at

--
Achilleas Mantzios
IT DEPT

On Thu, Feb 9, 2012 at 12:57 AM, Achilleas Mantzios
<achill@smadev.internal.net> wrote:
> On Πεμ 09 Φεβ 2012 02:32:37 Aleksey Tsalolikhin wrote:
>> I got an alert from check_postgres.pl today on a long-running query on
>> our production database, but our PostgreSQL 8.4.9 server log, which is
>> configured to log queries over 5 seconds long
>> ("log_min_duration_statement = 5000") does not show the query.
>>...
>> Can you think of some scenario where check_postgres.pl would see a
>> long-running query but it would not get logged by the database server?
>
> You should either look at the source of this perl script to see what it is
> doing ...

Thank you, Achilleas.  This issue came up today again - check_postgres reports
a long-running query, but no corresponding entry in the Postgres log even though
I have log_min_duration_statement turned on.

I followed your suggestion and found what query check_postgres uses (below).

Turns out the long running query is a transaction and it was never completed!

Now, is there any way for me to look inside that transaction and see
what the queries
are?

check_postgres query to identify long-running queries:

SELECTxact_start,
SUBSTR(current_query,0,100) AS current_query,
client_addr,
client_port,
procpid,
COALESCE(ROUND(EXTRACT(epoch FROM now()-query_start)),0) AS qtime,
datname,
usename
FROM pg_stat_activity
WHERE current_query <> '<IDLE>'  AND usename <> 'postgres'
ORDER BY xact_start, procpid DESC;

My long-running query that is in the middle of a transaction:

          xact_start          |     current_query     | client_addr |
client_port | procpid | qtime | datname |  usename

------------------------------+-----------------------+-------------+-------------+---------+-------+---------+-----------
 2012-03-07 09:53:15.49363-08 | <IDLE> in transaction |             |
        -1 |   31881 |  6824 | [redacted]     | [redacted]
(1 row)

Thanks,
Aleksey