survey: pg_stat_statements total_time and entry deallocation

From: Jeremy Schneider <schnjere(at)amazon(dot)com>
To: "pgsql-general(at)postgresql(dot)org" <pgsql-general(at)postgresql(dot)org>
Subject: survey: pg_stat_statements total_time and entry deallocation
Date: 2018-09-10 22:57:09
Message-ID: 0e8b7eb4-1621-2c53-6144-af095e64b787@amazon.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

TLDR: can you run this query on your prod DB and post the results?
=====

The default value of pg_stat_statements.max is 5000. Nonetheless, I was
recently trying to track down a SQL that did some temp I/O on a system
and discovered that I could only find it in pg_stat_statements if I used
\watch 1 and left a terminal open... that is, pg_stat_statements was
deleting SQL statements from memory every second.

The code to manage deallocation of entries is well over 10 years old. 
When it needs space for a new SQL and all <max> entries are already
allocated, it simply removes the bottom 5% by execution count.  There's
a comment that's been in there since the beginning, asking a question:
should deallocation reflect execution time and/or buffer usage instead
of execution count?

I'm most interested in total_time (I think if buffer access matters then
total_time will reflect that).  This made me curious about the
distribution of how total execution time is represented in
pg_stat_statements on a busy system. I got ahold of some friends running
busy, large postgres databases and had them run this simple query to
show how total_time is distributed across pg_stat_statements.  Here's
the query and results:

select
bucket
,count(*) entries
,max(calls) max_calls
,round(sum(total_time)) total_time
,round((100*sum(total_time)/avg(total_total_time))::numeric,2) pct_time
,round(sum(rows)) "rows"
,round((100*sum(rows)/avg(total_rows))::numeric,2) pct_rows
from
(
select
ntile(20) over (order by calls) bucket
,calls
,total_time
,sum(total_time) over () total_total_time
,rows
,sum(rows) over () total_rows
from pg_stat_statements
) stmts
group by rollup(bucket) order by bucket;

----- Verification:

select current_setting('pg_stat_statements.max');
current_setting
-----------------
5000

----- System 1:

bucket | entries | max_calls | total_time | pct_time | rows | pct_rows
--------+---------+-------------+------------+----------+-------------+----------
1 | 247 | 2 | 169 | 0.00 | 375 | 0.00
2 | 247 | 2 | 90 | 0.00 | 49 | 0.00
3 | 247 | 2 | 305 | 0.00 | 99 | 0.00
4 | 247 | 3 | 353 | 0.00 | 550 | 0.00
5 | 247 | 8 | 148 | 0.00 | 1609 | 0.00
6 | 247 | 44 | 1082 | 0.00 | 8912 | 0.00
7 | 247 | 73 | 2515 | 0.00 | 8734 | 0.00
8 | 247 | 117 | 5922 | 0.00 | 15690 | 0.00
9 | 247 | 292 | 43513 | 0.00 | 92579 | 0.00
10 | 247 | 851 | 20992 | 0.00 | 183895 | 0.00
11 | 247 | 4260 | 109540 | 0.00 | 811519 | 0.00
12 | 247 | 4682 | 278213 | 0.00 | 1113520 | 0.00
13 | 247 | 5009 | 295912 | 0.00 | 1197532 | 0.00
14 | 247 | 5379 | 312627 | 0.00 | 1280930 | 0.00
15 | 247 | 12298 | 541302 | 0.01 | 1954252 | 0.01
16 | 247 | 30573 | 1252066 | 0.01 | 6388232 | 0.02
17 | 247 | 62390 | 2139082 | 0.03 | 10699710 | 0.04
18 | 247 | 362514 | 7901250 | 0.09 | 181476105 | 0.64
19 | 246 | 3311178 | 4823142913 | 56.53 | 416459495 | 1.47
20 | 246 | 11373074151 | 3696341402 | 43.32 | 27693002500 | 97.80
[NULL] | 4938 | 11373074151 | 8532389397 | 100.00 | 28314696287 | 100.00

----- System 2:

bucket | entries | max_calls | total_time | pct_time | rows | pct_rows
--------+---------+------------+------------+----------+-------------+----------
1 | 244 | 2 | 242 | 0.00 | 570 | 0.00
2 | 244 | 2 | 13 | 0.00 | 36 | 0.00
3 | 244 | 2 | 14 | 0.00 | 34 | 0.00
4 | 244 | 2 | 16 | 0.00 | 34 | 0.00
5 | 244 | 2 | 14 | 0.00 | 38 | 0.00
6 | 244 | 2 | 14 | 0.00 | 68 | 0.00
7 | 244 | 2 | 14 | 0.00 | 30 | 0.00
8 | 244 | 4 | 19 | 0.00 | 532 | 0.00
9 | 244 | 34 | 184 | 0.00 | 2547 | 0.00
10 | 244 | 202 | 10577 | 0.00 | 29682 | 0.00
11 | 244 | 644 | 23279 | 0.00 | 125213 | 0.00
12 | 244 | 1544 | 46987 | 0.00 | 348863 | 0.00
13 | 244 | 1943 | 90455 | 0.00 | 424748 | 0.00
14 | 244 | 2172 | 105795 | 0.00 | 502619 | 0.00
15 | 244 | 2349 | 115168 | 0.00 | 548606 | 0.00
16 | 244 | 2532 | 124633 | 0.00 | 593084 | 0.00
17 | 244 | 2834 | 134928 | 0.00 | 646622 | 0.00
18 | 244 | 38747 | 184982 | 0.00 | 1275064 | 0.01
19 | 244 | 2334761 | 3496474265 | 58.13 | 551602241 | 2.63
20 | 243 | 8743645771 | 2517902540 | 41.86 | 20380562694 | 97.34
[NULL] | 4879 | 8743645771 | 6015214139 | 100.00 | 20936663325 | 100.00

Would anyone else be willing to run this query against their prod box
and post the results?  Especially if it is using all 5000 entries in
pg_stat_statements? I for one would like to know just how confident I
should be in whether pg_stat_statements is representative of all the
activity on a large system!

-Jeremy

--
Jeremy Schneider
Database Engineer
Amazon Web Services

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Michael Paquier 2018-09-11 03:02:50 Re: scram-sha-256 authentication broken in FIPS mode
Previous Message Alessandro Gherardi 2018-09-10 14:52:00 Re: scram-sha-256 authentication broken in FIPS mode