Re: BUG #10123: Weird entries in pg_stat_activity - Mailing list pgsql-bugs

On Thu, Apr 24, 2014 at 12:18 PM, <maxim.boguk@gmail.com> wrote:

> The following bug has been logged on the website:
>
> Bug reference:      10123
> Logged by:          Maxim Boguk
> Email address:      maxim.boguk@gmail.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=3D'idle'... what's more they happened durin=
g
> backend idle state.
>
> To check what's going on I performed the following actions on production
> database:
> 1)set log_min_duration_statement=3D0 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=3D'idle' and xact_start is not null" |  grep -vE '^$|No rows'; slee=
p
> 0.1; done
>
> And yes, once-twice-trice per minute script output some interesting resul=
ts
> 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=3Didle
> xact_start=3D4 min ago
>
> Now what I found in the full database log for this pid:
>
> ...
>
> 2014-04-24 13:45:02 MSK 685 ****@**** 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 ****@**** 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 ****@**** from 127.0.0.1 [vxid:24/0 txid:0]
> [SELECT] LOG:  duration: 0.415 ms  statement: SELECT * FROM o_queries_que=
ue
> ...
>
> So it seems that sometime pg_stat_activity entry become alive with the ol=
d
> 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).
>

This sounds like the expected behavior. When state=3DIdle, the query field
shows the value of the *last* query that ran. See
http://www.postgresql.org/docs/9.3/static/monitoring-stats.html#PG-STAT-ACT=
IVITY-VIEW
.

Note that this was changed in 9.2, and at the same time the current_query
field was renamed to query to highlight this change.

The fact that xact_start shows something far in the past just means that
there is an open transaction that has been open since then.

--=20
 Magnus Hagander
 Me: http://www.hagander.net/
 Work: http://www.redpill-linpro.com/