Re: Inconsistency between pg_stat_activity and log_duration

On Tue, Feb 4, 2014 at 9:36 AM, Tatsuo Ishii <ishii(at)postgresql(dot)org> wrote:
> 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 WHERE c.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 that is the probable reason for the above mentioned behaviour.
As I understand here, the problem is that 'state' of backend is shown as
active along with 'query' which according to docs (If state is active this field
shows the currently executing query.) means that query is executing.

This statement holds true for simple query but for prepared statement
(using message 'P', 'B', 'D', 'E', 'S') it might not be completely right as
we update the state only after sync message which can confuse some
users as you have stated. However I don't think it is good idea to change
state in between different messages or at least with the current set of
states.

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

Do you think we can fix it in any easy way, or might be updating docs
can make users understand the current situation better?

With Regards,
Amit Kapila.
EnterpriseDB: http://www.enterprisedb.com