Re: Inconsistency between pg_stat_activity and log_duration

On Fri, Feb 7, 2014 at 10:43 AM, Amit Kapila <amit(dot)kapila16(at)gmail(dot)com> wrote:
> 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.

One more catch is that I think it can happen for simple query statements
as well, because we first logs the query end duration and then updates
the state and both are not related in code, so there is always a small
window during which this can happen.

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