Inconsistency between pg_stat_activity and log_duration - Mailing list pgsql-hackers

From Tatsuo Ishii
Subject Inconsistency between pg_stat_activity and log_duration
Date
Msg-id 20140204.130637.400047374338726225.t-ishii@sraoss.co.jp
Whole thread Raw
Responses Re: Inconsistency between pg_stat_activity and log_duration  (Amit Kapila <amit.kapila16@gmail.com>)
List pgsql-hackers
I found an interesting inconsistency between pg_stat_activity and
log_duration.

-[ RECORD 1
]----+---------------------------------------------------------------------------------------------------------------------------
datid            | 16392
datname          | test
pid              | 21815
usesysid         | 10
usename          | t-ishii
application_name | psql
client_addr      | 
client_hostname  | 
client_port      | -1
backend_start    | 2014-02-04 12:46:55.178688+09
xact_start       | 2014-02-04 12:47:27.210976+09
query_start      | 2014-02-04 12:47:27.210976+09
state_change     | 2014-02-04 12:47:27.210981+09
waiting          | f
state            | active
query            | select * from pg_stat_activity;

[snip]

-[ RECORD 3
]----+---------------------------------------------------------------------------------------------------------------------------
datid            | 16392
datname          | test
pid              | 21850
usesysid         | 10
usename          | t-ishii
application_name | pgbench
client_addr      | 
client_hostname  | 
client_port      | -1
backend_start    | 2014-02-04 12:47:11.233245+09
xact_start       | 2014-02-04 12:47:11.235236+09
query_start      | 2014-02-04 12:47:11.241084+09
state_change     | 2014-02-04 12:47:11.241085+09
waiting          | f
state            | active
query            | SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.oid = pgpool_regclass('pgbench_accounts') AND
c.relpersistence= 'u'
 

As you can see, at 2014-02-04 12:47:27.210981+09 the query "SELECT
count(*) FROM pg_catalog.pg_class..." is "active" and it seems still
running.

On the other side, Here is an excerpt from PostgreSQL log:

21850 2014-02-04 12:47:11.241 JST LOG:  execute pgpool21805/pgpool21805: SELECT count(*) FROM pg_catalog.pg_class AS c
WHEREc.oid = pgpool_regclass('pgbench_accounts') AND c.relpersistence = 'u'
 
21850 2014-02-04 12:47:11.241 JST LOG:  duration: 0.078 ms

The duration was shown as "0.078 ms" thus it seems the query has been
already finished.

The reason why pg_stat_activity thinks that the query in question is,
"sync" message has not been sent to the backend yet (at least from
what I read from postgres.c).

I think this inconsistency is not very intutive to users...

Best regards,
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese: http://www.sraoss.co.jp



pgsql-hackers by date:

Previous
From: Fujii Masao
Date:
Subject: Re: Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
Next
From: Noah Misch
Date:
Subject: Re: Triggers on foreign tables