Re: phantom long-running query (check_postgres.pl reports a long-running query, but the database logs don't show it) - Mailing list pgsql-general

From Aleksey Tsalolikhin
Subject Re: phantom long-running query (check_postgres.pl reports a long-running query, but the database logs don't show it)
Date
Msg-id CA+jMWodbXnusm52SLH2vvdFLyU3zytfreGR5Xu7LcpKBSTYrzQ@mail.gmail.com
Whole thread Raw
In response to Re: phantom long-running query (check_postgres.pl reports a long-running query, but the database logs don't show it)  (Achilleas Mantzios <achill@smadev.internal.net>)
List pgsql-general
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

pgsql-general by date:

Previous
From: Joe Abbate
Date:
Subject: FDWs, foreign servers and user mappings
Next
From: Daniele Varrazzo
Date:
Subject: Re: rounding a timestamp to nearest x seconds