Re: pg_stat_statements: calls under-estimation propagation

On Tue, Oct 1, 2013 at 12:48 AM, Daniel Farina-5 [via PostgreSQL]
<ml-node+s1045698n5772887h21(at)n5(dot)nabble(dot)com> wrote:
>
> On Sep 30, 2013 4:39 AM, "Sameer Thakur" <[hidden email]> wrote:
>>
>> > Also, for onlookers, I have changed this patch around to do the
>> > date-oriented stuff but want to look it over before stapling it up and
>> > sending it. If one cannot wait, one can look at
>> > https://github.com/fdr/postgres/tree/queryid. The squashed-version of
>> > that history contains a reasonable patch I think, but a re-read often
>> > finds something for me and I've only just completed it yesterday.
>> >
>>
>> I did the following
>> 1. Forked from fdr/postgres
>> 2. cloned branch queryid
>> 3. squashed
>> 22899c802571a57cfaf0df38e6c5c366b5430c74
>> d813096e29049667151a49fc5e5cf3d6bbe55702
>> picked
>> be2671a4a6aa355c5e8ae646210e6c8e0b84ecb5
>> 4. usual make/make install/create extension pg_stat_statements.
>> (pg_stat_statements.max=100).
>> 5. select * from pg_stat_statements_reset(), select * from
>> pgbench_tellers.
>> result below:
>>
>> userid | dbid | session_start | introduced
>> | query | query_id
>> | calls | total_time |
>> rows | shared_blks_hit | shared_blks_read | shared_blks_dirtied |
>> shared_blks_written | local_blks_hit | local_blks_read |
>> local_blks_dirtied | local_blks_written | t
>> emp_blks_read | temp_blks_written | blk_read_time | blk_write_time
>>
>> --------+-------+----------------------------------+---------------------------+-------------------------------------------+---------------------+-------+------------+
>>
>> ------+-----------------+------------------+---------------------+---------------------+----------------+-----------------+--------------------+--------------------+--
>> --------------+-------------------+---------------+----------------
>> 10 | 12900 | 2013-09-30 16:55:22.285113+05:30 | 1970-01-01
>> 05:30:00+05:30 | select * from pg_stat_statements_reset(); |
>> 2531907647060518039 | 1 | 0 |
>> 1 | 0 | 0 | 0 |
>> 0 | 0 | 0 |
>> 0 | 0 |
>> 0 | 0 | 0 | 0
>> 10 | 12900 | 2013-09-30 16:55:22.285113+05:30 | 1970-01-01
>> 05:30:00+05:30 | select * from pgbench_tellers ; |
>> 7580333025384382649 | 1 | 0 |
>> 10 | 1 | 0 | 0 |
>> 0 | 0 | 0 |
>> 0 | 0 |
>> 0 | 0 | 0 | 0
>> (2 rows)
>>
>>
>> I understand session_start and verified that it changes with each
>> database restart to reflect current time.
>
> It should only restart when the statistics file cannot be loaded.
>
> I am not sure why introduced
>
>> keeps showing the same "1970-01-01 05:30:00+05:30" value. I thought it
>> reflected the (most recent) time query statements statistics is added
>> to hashtable. Is this a bug?
>> Will continue to test and try and understand the code.
>
> Yes, a bug. There are a few calls to pgss store and I must be submitting a
> zero value for the introduction time in one of those cases.
>
> Heh, I thought that was fixed, but maybe I broke something. Like I said;
> preliminary. At the earliest I can look at this Wednesday, but feel free to
> amend and resubmit including my changes if you feel inclined and get to it
> first.

In pg_stat_statements.c line 1440
changed
if (instr == NULL)
to
if (instr == NULL || INSTR_TIME_IS_ZERO(instr->starttime))

This seemed to do the trick. I will continue to test some more.
regards
Sameer

--
View this message in context: http://postgresql.1045698.n5.nabble.com/pg-stat-statements-calls-under-estimation-propagation-tp5738128p5772930.html
Sent from the PostgreSQL - hackers mailing list archive at Nabble.com.