Re: pg_stat_statements: calls under-estimation propagation

On Tue, Oct 1, 2013 at 5:32 AM, Sameer Thakur <samthakur74(at)gmail(dot)com> wrote:
> On Tue, Oct 1, 2013 at 12:48 AM, Daniel Farina-5 [via PostgreSQL]
> <[hidden email]> 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.
>
> This seems to work fine.
> 1. Started the instance
> 2. Executed pg_stat_statements_reset(), select * from
> pgbench_history,select* from pgbench_tellers. Got the following in
> pg_stat_statements view
> userid | dbid | session_start |
> introduced | query |
> query_id | calls | tota
> l_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_wri
> tten | temp_blks_read | temp_blks_written | blk_read_time | blk_write_time
> --------+-------+----------------------------------+----------------------------------+-------------------------------------------+----------------------+-------+-----
> -------+------+-----------------+------------------+---------------------+---------------------+----------------+-----------------+--------------------+---------------
> -----+----------------+-------------------+---------------+----------------
> 10 | 12900 | 2013-10-01 17:43:26.667074+05:30 | 2013-10-01
> 17:43:43.724301+05:30 | select * from pgbench_history; |
> -165801328395488047 | 1 |
> 0 | 0 | 0 | 0 |
> 0 | 0 | 0 | 0 |
> 0 |
> 0 | 0 | 0 | 0 | 0
> 10 | 12900 | 2013-10-01 17:43:26.667074+05:30 | 2013-10-01
> 17:43:37.379785+05:30 | select * from pgbench_tellers; |
> 8376871363863945311 | 1 |
> 0 | 10 | 0 | 1 |
> 0 | 0 | 0 | 0 |
> 0 |
> 0 | 0 | 0 | 0 | 0
> 10 | 12900 | 2013-10-01 17:43:26.667074+05:30 | 2013-10-01
> 17:43:26.667178+05:30 | select * from pg_stat_statements_reset(); |
> -1061018443194138344 | 1 |
> 0 | 1 | 0 | 0 |
> 0 | 0 | 0 | 0 |
> 0 |
> 0 | 0 | 0 | 0 | 0
> (3 rows)
>
> Then restarted the server and saw pg_stat_statements view again.
>
> userid | dbid | session_start |
> introduced | query |
> query_id | calls | tota
> l_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_wri
> tten | temp_blks_read | temp_blks_written | blk_read_time | blk_write_time
> --------+-------+----------------------------------+----------------------------------+-------------------------------------------+----------------------+-------+-----
> -------+------+-----------------+------------------+---------------------+---------------------+----------------+-----------------+--------------------+---------------
> -----+----------------+-------------------+---------------+----------------
> 10 | 12900 | 2013-10-01 17:43:26.667074+05:30 | 2013-10-01
> 17:45:15.130261+05:30 | select * from pgbench_history; |
> -165801328395488047 | 1 |
> 0 | 0 | 0 | 0 |
> 0 | 0 | 0 | 0 |
> 0 |
> 0 | 0 | 0 | 0 | 0
> 10 | 12900 | 2013-10-01 17:43:26.667074+05:30 | 2013-10-01
> 17:45:15.130266+05:30 | select * from pg_stat_statements ; |
> -247576122750898541 | 1 |
> 0 | 3 | 0 | 0 |
> 0 | 0 | 0 | 0 |
> 0 |
> 0 | 0 | 0 | 0 | 0
> 10 | 12900 | 2013-10-01 17:43:26.667074+05:30 | 2013-10-01
> 17:45:15.130271+05:30 | select * from pgbench_tellers; |
> 8376871363863945311 | 1 |
> 0 | 10 | 0 | 1 |
> 0 | 0 | 0 | 0 |
> 0 |
> 0 | 0 | 0 | 0 | 0
> 10 | 12900 | 2013-10-01 17:43:26.667074+05:30 | 2013-10-01
> 17:45:15.130276+05:30 | select * from pg_stat_statements_reset(); |
> -1061018443194138344 | 1 |
> 0 | 1 | 0 | 0 |
> 0 | 0 | 0 | 0 |
> 0 |
> 0 | 0 | 0 | 0 | 0
> (4 rows)
>
> Correctly, session start remains same after restart for all queries
> and introduced time differs slightly reflecting re-introduction of
> statistics into hashtable after reading from statistics file. Also,
> correctly, queryid remains same for all queries.
>
> Now shutdown and delete pg_stat_statements.stat under data/global.
> Restart again and check pg_stat_statements view.
>
> userid | dbid | session_start | introduced | query | query_id | calls
> | total_time | rows | shared_blks_hit | shared_blks_read |
> shared_blks_dirtied | shared_blks_wri
> tten | local_blks_hit | local_blks_read | local_blks_dirtied |
> local_blks_written | temp_blks_read | temp_blks_written |
> blk_read_time | blk_write_time
> --------+------+---------------+------------+-------+----------+-------+------------+------+-----------------+------------------+---------------------+----------------
> -----+----------------+-----------------+--------------------+--------------------+----------------+-------------------+---------------+----------------
> (0 rows)
>
> Correctly it has been reset.
>
> regards
> Sameer

Looks pretty good. Do you want to package up the patch with your
change and do the honors and re-submit it? Thanks for helping out so
much!