From: | maxim(dot)boguk(at)gmail(dot)com |
---|---|
To: | pgsql-bugs(at)postgresql(dot)org |
Subject: | BUG #10123: Weird entries in pg_stat_activity |
Date: | 2014-04-24 10:18:27 |
Message-ID: | 20140424101827.2714.39486@wrigleys.postgresql.org |
Views: | Raw Message | Whole Thread | Download mbox | Resend email |
Thread: | |
Lists: | pgsql-bugs |
The following bug has been logged on the website:
Bug reference: 10123
Logged by: Maxim Boguk
Email address: maxim(dot)boguk(at)gmail(dot)com
PostgreSQL version: 9.2.8
Operating system: Linux
Description:
Hi everyone,
During debug of the weird nagios database alerts about long transactions I
found that sometime pg_stat_activity contains very weird entries with
xact_start NOT NULL and state='idle'... what's more they happened during
backend idle state.
To check what's going on I performed the following actions on production
database:
1)set log_min_duration_statement=0 to see ALL database queries
2)run single line bash script to check for weird entries:
while true; do psql -x -X -c "select now() as ts,now()-xact_start as
tx_age, now()-state_change as change_age,* from pg_stat_activity where
state='idle' and xact_start is not null" | grep -vE '^$|No rows'; sleep
0.1; done
And yes, once-twice-trice per minute script output some interesting results
such as:
-[ RECORD 1
]----+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
ts | 2014-04-24 13:49:03.498354+04
tx_age | 00:04:01.283106
change_age | 00:04:01.279373
datid | 16385
datname | *******
pid | 685
usesysid | 16384
usename | *******
application_name |
client_addr | 127.0.0.1
client_hostname |
client_port | 37461
backend_start | 2014-04-24 13:30:03.275711+04
xact_start | 2014-04-24 13:45:02.215248+04
query_start | 2014-04-24 13:45:02.215248+04
state_change | 2014-04-24 13:45:02.218981+04
waiting | f
state | idle
query |
| SELECT cache.save_response(
| *****
| );
State=idle
xact_start=4 min ago
Now what I found in the full database log for this pid:
...
2014-04-24 13:45:02 MSK 685 ****(at)**** from 127.0.0.1 [vxid:24/0 txid:0]
[SELECT] LOG: duration: 3.703 ms statement:
SELECT cache.save_response(...)
-- no queries between 13:45 and 13:50 at all!
2014-04-24 13:50:01 MSK 685 ****(at)**** from 127.0.0.1 [vxid:24/0 txid:0]
[SELECT] LOG: duration: 0.962 ms statement: select 1
2014-04-24 13:50:01 MSK 685 ****(at)**** from 127.0.0.1 [vxid:24/0 txid:0]
[SELECT] LOG: duration: 0.415 ms statement: SELECT * FROM o_queries_queue
...
So it seems that sometime pg_stat_activity entry become alive with the old
information (it shows xact_start from the last executed query in backend,
even if that query finished long time ago).
I know about asynchronous behavior of pg_stat_activity but getting
xact_start from deep past seems wrong for me.
What's more: i tested that problem on another databases - and found they
have same effect (so it doesn't look like a problem local to that single
exact database).
Kind Regards,
Maksym
From | Date | Subject | |
---|---|---|---|
Next Message | Magnus Hagander | 2014-04-24 10:26:09 | Re: BUG #10123: Weird entries in pg_stat_activity |
Previous Message | Claudio Nieder | 2014-04-24 09:54:46 | Possible transaction bug with isolation level serialisable? |