Re: BUG #10123: Weird entries in pg_stat_activity

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

On Thu, Apr 24, 2014 at 12:18 PM, <maxim(dot)boguk(at)gmail(dot)com> wrote:

> 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).
>

This sounds like the expected behavior. When state=Idle, 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-ACTIVITY-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.

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

On 2014-04-24 12:26:09 +0200, Magnus Hagander wrote:
> On Thu, Apr 24, 2014 at 12:18 PM, <maxim(dot)boguk(at)gmail(dot)com> wrote:
> > ]----+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> > 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(
> > | *****
> > | );

> This sounds like the expected behavior. When state=Idle, 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-ACTIVITY-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.

I don't think that's true. In that case the state should have been idle
in transaction, no?

I think there's a pgstat_report_xact_timestamp(0) missing from
xact.c:PrepareTransaction(). There's no point in reporting a prepared
xact's starttime in a backend that's not associated with it anymore.

Maxim, are you using prepared transactions?

Greetings,

Andres Freund

--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

On Thu, Apr 24, 2014 at 12:44 PM, Andres Freund <andres(at)2ndquadrant(dot)com>wrote:

> On 2014-04-24 12:26:09 +0200, Magnus Hagander wrote:
> > On Thu, Apr 24, 2014 at 12:18 PM, <maxim(dot)boguk(at)gmail(dot)com> wrote:
> > >
> ]----+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> > > 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(
> > > | *****
> > > | );
>
> > This sounds like the expected behavior. When state=Idle, 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-ACTIVITY-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.
>
> I don't think that's true. In that case the state should have been idle
> in transaction, no?
>

Oh, good point. Clearly I was too cofused on the "query" field. Sorry about
that, and thanks for spotting it!

I think there's a pgstat_report_xact_timestamp(0) missing from
> xact.c:PrepareTransaction(). There's no point in reporting a prepared
> xact's starttime in a backend that's not associated with it anymore.

> Maxim, are you using prepared transactions?
>

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

On Thu, Apr 24, 2014 at 8:44 PM, Andres Freund <andres(at)2ndquadrant(dot)com>wrote:

> On 2014-04-24 12:26:09 +0200, Magnus Hagander wrote:
> > On Thu, Apr 24, 2014 at 12:18 PM, <maxim(dot)boguk(at)gmail(dot)com> wrote:
> > >
> ]----+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> > > 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(
> > > | *****
> > > | );
>
> > This sounds like the expected behavior. When state=Idle, 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-ACTIVITY-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.
>
> I don't think that's true. In that case the state should have been idle
> in transaction, no?
>
> I think there's a pgstat_report_xact_timestamp(0) missing from
> xact.c:PrepareTransaction(). There's no point in reporting a prepared
> xact's starttime in a backend that's not associated with it anymore.
>
> Maxim, are you using prepared transactions?
>
>
No, project isn't using prepared transactions. I absolutely sure.
postgres=# show max_prepared_transactions;
max_prepared_transactions
---------------------------
0

What strange - that exact pg_stat_activity entry stayed with xact_start
NULL for 4 minute after the last query for this pid finished, and after
that somehow got the live xact_start again (and in the next check iteration
after 0.1s xact_start become NULL again for that pid).
tx_age can vary, i seen anything between 1 second and 30 minutes... all
related to idle backends (so state='idle' is correct).

Kind Regards,
Maksym

Andres Freund <andres(at)2ndquadrant(dot)com> writes:
> I think there's a pgstat_report_xact_timestamp(0) missing from
> xact.c:PrepareTransaction(). There's no point in reporting a prepared
> xact's starttime in a backend that's not associated with it anymore.

> Maxim, are you using prepared transactions?

Even if he were, that wouldn't explain this report, because the displayed
latest-query would have to have been a PREPARE TRANSACTION, no?

However, regardless of exactly what's going on here, I think you're
probably right that PrepareTransaction ought to do
pgstat_report_xact_timestamp(0) once it exits the transaction state
locally. The definition of that field is that it's null whenever the
session isn't inside a transaction, and once we do PREPARE, we aren't.

regards, tom lane

On 2014-04-24 12:37:15 -0400, Tom Lane wrote:
> Andres Freund <andres(at)2ndquadrant(dot)com> writes:
> > I think there's a pgstat_report_xact_timestamp(0) missing from
> > xact.c:PrepareTransaction(). There's no point in reporting a prepared
> > xact's starttime in a backend that's not associated with it anymore.
>
> > Maxim, are you using prepared transactions?
>
> Even if he were, that wouldn't explain this report, because the displayed
> latest-query would have to have been a PREPARE TRANSACTION, no?

Right. I think there's some other contents that could potentially end up
there, but surely not the SELECT Maxim is reporting. Especially not as
there seem to be several minutes inbetween the pg_stat_get_activity call
and the last state change...

> However, regardless of exactly what's going on here, I think you're
> probably right that PrepareTransaction ought to do
> pgstat_report_xact_timestamp(0) once it exits the transaction state
> locally. The definition of that field is that it's null whenever the
> session isn't inside a transaction, and once we do PREPARE, we aren't.

Thanks for fixing it.

I don't really have a clue what's going on here. I don't believe
pgstat.c's changecount thing is 100% safe, but that doesn't explain the
problem here.

Greetings,

Andres Freund

--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

maxim(dot)boguk(at)gmail(dot)com writes:
> 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: 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).

So can you provide a self-contained test case for this? I tried to
reproduce it here without much success, and I don't see a code path
other than PREPARE TRANSACTION that could lead to this.

regards, tom lane

On Fri, Apr 25, 2014 at 4:38 AM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:

> maxim(dot)boguk(at)gmail(dot)com writes:
> > 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: 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).
>
> So can you provide a self-contained test case for this? I tried to
> reproduce it here without much success, and I don't see a code path
> other than PREPARE TRANSACTION that could lead to this.
>
> regards, tom lane
>

I going to work on test case over weekend.
Initial quick and dirty attempts to reproduce outside of complicated
production environments provided no results yet.

What I almost sure now that reproducing of the bug requires a mix of very
active connections to the database (with a lot of requests per second) with
semi-idle connections.
And that transient problem affects only these semi-idle connections.

I will provide an update when I get more information.

Kind Regards,
Maksym

On Fri, Apr 25, 2014 at 11:04 AM, Maxim Boguk <maxim(dot)boguk(at)gmail(dot)com> wrote:

>
>
>
> On Fri, Apr 25, 2014 at 4:38 AM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>
>> maxim(dot)boguk(at)gmail(dot)com writes:
>> > 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: 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).
>>
>> So can you provide a self-contained test case for this? I tried to
>> reproduce it here without much success, and I don't see a code path
>> other than PREPARE TRANSACTION that could lead to this.
>>
>> regards, tom lane
>>
>
> I going to work on test case over weekend.
> Initial quick and dirty attempts to reproduce outside of complicated
> production environments provided no results yet.
>
> What I almost sure now that reproducing of the bug requires a mix of very
> active connections to the database (with a lot of requests per second) with
> semi-idle connections.
> And that transient problem affects only these semi-idle connections.
>
> I will provide an update when I get more information.
>
> Kind Regards,
> Maksym
>

Unfortunately even if problem can be seen in at least 10 different project
and db-servers, creating reproducible test case had not been successful.
So I decided work with gdb on the real database.

At this moment I dig only to the pgstat.c :
pgstat_read_current_status(void) function.

gdb:

set print pretty on
b pgstat.c:2796 if ((localentry->st_procpid>0) &&
(localentry->st_xact_start_timestamp>0) &&
(localentry->st_state==STATE_IDLE))
cont

2796 line in 9.3.4 source is pgstat_read_current_status function just after
memcpy(localentry, (char *) beentry,
sizeof(PgBackendStatus));

After short time running:
select pg_sleep(0.01); 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;
in loop in process under gdb I got conditional breakpoint fired with the
next results:

(gdb) cont
Continuing.

Breakpoint 1, pgstat_read_current_status () at
/tmp/buildd/postgresql-9.3-9.3.4/build/../src/backend/postmaster/pgstat.c:2796
2796 strcpy(localappname, (char *)
beentry->st_appname);
(gdb) p *localentry
$1 = {
st_changecount = 1222944,
st_procpid = 16215,
st_proc_start_timestamp = 454324143169490,
st_xact_start_timestamp = 454324206165363,
st_activity_start_timestamp = 454324206165363,
st_state_start_timestamp = 454324206165650,
st_databaseid = 16423,
st_userid = 25078444,
st_clientaddr = {
addr = {
ss_family = 2,
__ss_align = 0,
__ss_padding = '\000' <repeats 111 times>
},
salen = 16
},
st_clienthostname = 0x7fac4344fbe0 "",
st_waiting = 0 '\000',
st_state = STATE_IDLE,
st_appname = 0x7fac624d8ff0 "",
st_activity = 0x7fac624e4bb0 "SELECT
\"last_host_hour_accumulation_flag\".\"id\",
\"last_host_hour_accumulation_flag\".\"day\",
\"last_host_hour_accumulation_flag\".\"hour\",
\"last_host_hour_accumulation_flag\".\"type_id\", \"last_host_hour_accum"...
}

Please note that the:
st_xact_start_timestamp = 454324206165363,
st_activity_start_timestamp = 454324206165363,

and in the same time:
st_state = STATE_IDLE

On the next iteration after 0.01 second st_proc_start_timestamp and
st_activity_start_timestamp returned to 0 again.

Now I have no good idea how to perform the future debug because
BackendStatusArray is shared memory structure with every backend writing
information into it (so I can't set a conditional breakpoint in specific
process)
Ideas welcome.

Kind Regards,
Maksym