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.

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

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