Thread: survey: pg_stat_statements total_time and entry deallocation
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:
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
=====
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
Here is some data from our production. I hope it can be of any use to you.
----- System 1:
hiper=> 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;
bucket | entries | max_calls | total_time | pct_time | rows | pct_rows
--------+---------+-----------+------------+----------+------------+----------
1 | 245 | 71 | 4745479 | 0.38 | 640677 | 0.04
2 | 245 | 96 | 22151762 | 1.76 | 236827 | 0.01
3 | 245 | 122 | 9028387 | 0.72 | 297861 | 0.02
4 | 244 | 167 | 4711705 | 0.38 | 328928 | 0.02
5 | 244 | 228 | 9490670 | 0.76 | 337712 | 0.02
6 | 244 | 305 | 7296024 | 0.58 | 273740 | 0.02
7 | 244 | 394 | 35828651 | 2.85 | 1140064 | 0.07
8 | 244 | 540 | 34180388 | 2.72 | 1313171 | 0.08
9 | 244 | 711 | 29748121 | 2.37 | 865894 | 0.05
10 | 244 | 989 | 12864432 | 1.02 | 1665529 | 0.10
11 | 244 | 1507 | 4009346 | 0.32 | 1295032 | 0.08
12 | 244 | 2511 | 13444734 | 1.07 | 4711699 | 0.30
13 | 244 | 4567 | 401096681 | 31.94 | 3386595 | 0.21
14 | 244 | 8086 | 4750899 | 0.38 | 8236002 | 0.52
15 | 244 | 13356 | 19875345 | 1.58 | 6040996 | 0.38
16 | 244 | 22454 | 23361859 | 1.86 | 16906926 | 1.06
17 | 244 | 59660 | 68633113 | 5.46 | 40170089 | 2.52
18 | 244 | 141667 | 59768727 | 4.76 | 76054887 | 4.77
19 | 244 | 431946 | 330488976 | 26.31 | 213238961 | 13.38
20 | 244 | 170978486 | 160486607 | 12.78 | 1216933189 | 76.34
| 4883 | 170978486 | 1255961906 | 100.00 | 1594074779 | 100.00
(21 rows)
hiper=> select current_setting('pg_stat_statements.max');
current_setting
-----------------
5000
(1 row)
In addition to Kim's results and my initial data, a handful of people have forwarded results to me over the past few weeks. Here's what came my way, aggregated and anonymized.
System #7 is the particularly interesting one. Note that if this user had *not* increased their max to 10k, the SQL statements responsible for about 20% of their databases time would have been rolled off and lost from pg_stat_statements. On most systems the problem is actually a lot smaller than I expected, but there is still a case here where people might lose data from pg_stat_statements which they wouldn't want to lose. Might be worth a discussion about switching to sorting based on total_time instead of calls?
-Jeremy
---------- pg_stat_statements.max = 5000
SYSTEM 1:
bucket | entries | max_calls | total_time | pct_time | rows | pct_rows
--------+---------+-------------+-------------+----------+--------------+----------
1 | 243 | 4 | 2172 | 0.00 | 12395 | 0.00
2 | 243 | 8 | 2466 | 0.00 | 36148 | 0.00
3 | 243 | 15 | 6368 | 0.00 | 34711 | 0.00
4 | 243 | 28 | 17801 | 0.00 | 59143 | 0.00
5 | 243 | 52 | 23631 | 0.00 | 197337 | 0.00
6 | 243 | 126 | 119005 | 0.00 | 146798 | 0.00
7 | 243 | 275 | 184864 | 0.00 | 402160 | 0.00
8 | 243 | 648 | 672907 | 0.00 | 948613 | 0.00
9 | 243 | 1616 | 1175448 | 0.01 | 3011254 | 0.00
10 | 242 | 3775 | 803799 | 0.00 | 6308289 | 0.00
11 | 242 | 8572 | 3315890 | 0.02 | 13489707 | 0.00
12 | 242 | 19436 | 7747413 | 0.04 | 22958217 | 0.01
13 | 242 | 55933 | 8572104 | 0.05 | 45162385 | 0.01
14 | 242 | 168402 | 22795122 | 0.13 | 135961496 | 0.04
15 | 242 | 413909 | 62500891 | 0.35 | 352699202 | 0.11
16 | 242 | 744639 | 94332579 | 0.53 | 386606008 | 0.12
17 | 242 | 1374743 | 257049472 | 1.45 | 2085014682 | 0.64
18 | 242 | 3891776 | 840326001 | 4.75 | 2183808874 | 0.67
19 | 242 | 22378695 | 1544711644 | 8.73 | 10972242140 | 3.39
20 | 242 | 15589184235 | 14858568512 | 83.93 | 307346618022 | 94.99
| 4849 | 15589184235 | 17702928088 | 100.00 | 323555717581 | 100.00
SYSTEM 2:
bucket | entries | max_calls | total_time | pct_time | rows | pct_rows
--------+---------+-------------+------------+----------+---------------+----------
1 | 244 | 17 | 16191 | 0.00 | 48204 | 0.00
2 | 244 | 64 | 271114 | 0.00 | 363019 | 0.00
3 | 244 | 100 | 366725 | 0.00 | 671762 | 0.00
4 | 244 | 140 | 180140 | 0.00 | 1164382 | 0.00
5 | 244 | 186 | 608551 | 0.01 | 1768865 | 0.00
6 | 244 | 243 | 541205 | 0.01 | 2349195 | 0.00
7 | 244 | 309 | 456749 | 0.01 | 3152989 | 0.00
8 | 244 | 393 | 658530 | 0.01 | 4168022 | 0.00
9 | 244 | 510 | 1748446 | 0.02 | 5324083 | 0.00
10 | 244 | 660 | 837506 | 0.01 | 6175995 | 0.00
11 | 244 | 839 | 1238649 | 0.01 | 7998575 | 0.00
12 | 244 | 1161 | 1155261 | 0.01 | 8722566 | 0.00
13 | 244 | 1777 | 1590755 | 0.02 | 10255668 | 0.00
14 | 244 | 3757 | 1892540 | 0.02 | 12267192 | 0.00
15 | 244 | 7503 | 1970249 | 0.02 | 13806280 | 0.00
16 | 244 | 14022 | 2246406 | 0.02 | 9873244 | 0.00
17 | 244 | 27798 | 3710787 | 0.04 | 15258889 | 0.00
18 | 244 | 60297 | 6049492 | 0.07 | 27484995 | 0.00
19 | 243 | 263828 | 6925772 | 0.08 | 61324608 | 0.00
20 | 243 | 11359462345 | 9082897956 | 99.64 | 1914448979042 | 99.99
| 4878 | 11359462345 | 9115363026 | 100.00 | 1914641157575 | 100.00
---------- pg_stat_statements.max = 10000
SYSTEM 3:
bucket | entries | max_calls | total_time | pct_time | rows | pct_rows
--------+---------+-----------+------------+----------+-------------+----------
1 | 405 | 1 | 1903 | 0.00 | 24 | 0.00
2 | 405 | 1 | 11492 | 0.00 | 20 | 0.00
3 | 405 | 1 | 1755 | 0.00 | 61 | 0.00
4 | 405 | 1 | 1628 | 0.00 | 71 | 0.00
5 | 405 | 1 | 1758 | 0.00 | 16 | 0.00
6 | 405 | 1 | 1867 | 0.00 | 18 | 0.00
7 | 404 | 1 | 1596 | 0.00 | 23 | 0.00
8 | 404 | 1 | 1679 | 0.00 | 13 | 0.00
9 | 404 | 1 | 2984 | 0.00 | 23 | 0.00
10 | 404 | 1 | 6016 | 0.00 | 248 | 0.00
11 | 404 | 1 | 1714 | 0.00 | 49 | 0.00
12 | 404 | 1 | 1732 | 0.00 | 17 | 0.00
13 | 404 | 6 | 19308 | 0.01 | 1436 | 0.00
14 | 404 | 23 | 27046782 | 9.51 | 4181 | 0.00
15 | 404 | 90 | 1905408 | 0.67 | 18336 | 0.00
16 | 404 | 644 | 93061 | 0.03 | 111651 | 0.00
17 | 404 | 3083 | 12994763 | 4.57 | 516112 | 0.00
18 | 404 | 24168 | 234976 | 0.08 | 5065065 | 0.05
19 | 404 | 105507 | 9468647 | 3.33 | 24062919 | 0.22
20 | 404 | 749065295 | 232561858 | 81.78 | 10913252211 | 99.73
| 8086 | 749065295 | 284360925 | 100.00 | 10943032494 | 100.00
SYSTEM 4:
bucket | entries | max_calls | total_time | pct_time | rows | pct_rows
--------+---------+------------+------------+----------+------------+----------
1 | 346 | 1 | 19667 | 0.00 | 2 | 0.00
2 | 346 | 1 | 49980 | 0.01 | 4 | 0.00
3 | 346 | 1 | 34046 | 0.00 | 8 | 0.00
4 | 346 | 1 | 102305 | 0.01 | 43 | 0.00
5 | 346 | 1 | 51369 | 0.01 | 5 | 0.00
6 | 346 | 1 | 18724 | 0.00 | 5 | 0.00
7 | 346 | 1 | 32055 | 0.00 | 43 | 0.00
8 | 346 | 1 | 35607 | 0.01 | 45 | 0.00
9 | 346 | 1 | 16091 | 0.00 | 31 | 0.00
10 | 346 | 1 | 18696 | 0.00 | 6 | 0.00
11 | 346 | 1 | 88879 | 0.01 | 5 | 0.00
12 | 346 | 1 | 18936 | 0.00 | 9 | 0.00
13 | 346 | 1 | 2720 | 0.00 | 408 | 0.00
14 | 346 | 1 | 33465 | 0.00 | 13 | 0.00
15 | 346 | 1 | 22200 | 0.00 | 2 | 0.00
16 | 346 | 3 | 1516109 | 0.22 | 369 | 0.00
17 | 346 | 48 | 47541581 | 6.96 | 36564 | 0.00
18 | 346 | 13118 | 30152991 | 4.41 | 822077 | 0.01
19 | 346 | 151800 | 13622497 | 1.99 | 22931644 | 0.26
20 | 346 | 1830494680 | 589642951 | 86.33 | 8682168726 | 99.73
| 6920 | 1830494680 | 683020868 | 100.00 | 8705960009 | 100.00
SYSTEM 5:
bucket | entries | max_calls | total_time | pct_time | rows | pct_rows--------+---------+------------+-------------+----------+-------------+----------
1 | 475 | 9 | 893189 | 0.01 | 958040 | 0.00
2 | 475 | 19 | 2462391 | 0.02 | 6248719 | 0.03
3 | 475 | 34 | 20795485 | 0.15 | 61456170 | 0.27
4 | 475 | 54 | 192705939 | 1.38 | 29269715 | 0.13
5 | 475 | 76 | 20947539 | 0.15 | 62108105 | 0.27
6 | 475 | 105 | 30439360 | 0.22 | 29579780 | 0.13
7 | 475 | 149 | 112750582 | 0.81 | 12169241 | 0.05
8 | 475 | 197 | 59168134 | 0.42 | 23153432 | 0.10
9 | 475 | 233 | 270201714 | 1.93 | 47299193 | 0.21
10 | 475 | 344 | 49366939 | 0.35 | 26034858 | 0.11
11 | 474 | 480 | 147016160 | 1.05 | 25381678 | 0.11
12 | 474 | 722 | 128961149 | 0.92 | 29928478 | 0.13
13 | 474 | 1072 | 281782913 | 2.01 | 85346789 | 0.37
14 | 474 | 1832 | 72278183 | 0.52 | 70689440 | 0.31
15 | 474 | 2972 | 1476021946 | 10.55 | 196298836 | 0.86
16 | 474 | 5707 | 967959256 | 6.92 | 183873573 | 0.80
17 | 474 | 12876 | 1654604242 | 11.83 | 865935480 | 3.77
18 | 474 | 30402 | 3708901952 | 26.51 | 1213651635 | 5.29
19 | 474 | 250514 | 1028521943 | 7.35 | 7294711094 | 31.77
20 | 474 | 1095421646 | 3765557605 | 26.91 | 12693321192 | 55.29
[NULL] | 9490 | 1095421646 | 13991336620 | 100.00 | 22957415448 | 100.00
SYSTEM 6:
bucket | entries | max_calls | total_time | pct_time | rows | pct_rows
--------+---------+-----------+------------+----------+------------+----------
1 | 489 | 1 | 19089 | 0.01 | 227 | 0.00
2 | 489 | 1 | 17191 | 0.01 | 63 | 0.00
3 | 489 | 1 | 16191 | 0.01 | 3 | 0.00
4 | 489 | 1 | 19004 | 0.01 | 46 | 0.00
5 | 489 | 1 | 15455 | 0.01 | 2929 | 0.00
6 | 488 | 1 | 15646 | 0.01 | 3 | 0.00
7 | 488 | 1 | 14648 | 0.01 | 11 | 0.00
8 | 488 | 1 | 42245 | 0.02 | 4 | 0.00
9 | 488 | 1 | 25555 | 0.01 | 67 | 0.00
10 | 488 | 1 | 22782 | 0.01 | 3137 | 0.00
11 | 488 | 1 | 9012 | 0.00 | 110 | 0.00
12 | 488 | 1 | 22773 | 0.01 | 76 | 0.00
13 | 488 | 1 | 27693 | 0.01 | 3 | 0.00
14 | 488 | 3 | 1526935 | 0.65 | 6347 | 0.00
15 | 488 | 14 | 1563175 | 0.67 | 32264 | 0.00
16 | 488 | 65 | 2159331 | 0.92 | 175479 | 0.01
17 | 488 | 658 | 26080111 | 11.11 | 548347 | 0.02
18 | 488 | 15043 | 71774949 | 30.57 | 2366723 | 0.09
19 | 488 | 139639 | 35335687 | 15.05 | 44022110 | 1.72
20 | 488 | 80924635 | 96044962 | 40.91 | 2512784413 | 98.16
| 9765 | 80924635 | 234752432 | 100.00 | 2559942362 | 100.00
SYSTEM 7:
bucket | entries | max_calls | total_time | pct_time | rows | pct_rows
--------+---------+-----------+-------------+----------+-------------+----------
1 | 474 | 1 | 425784 | 0.00 | 361694 | 0.00
2 | 474 | 2 | 22314020 | 0.22 | 2696158 | 0.00
3 | 474 | 3 | 35609364 | 0.35 | 121351894 | 0.15
4 | 474 | 5 | 69937281 | 0.69 | 103883776 | 0.13
5 | 474 | 7 | 85452745 | 0.84 | 164374678 | 0.20
6 | 473 | 11 | 19180309 | 0.19 | 7020715 | 0.01
7 | 473 | 22 | 51312437 | 0.50 | 19251387 | 0.02
8 | 473 | 55 | 169262450 | 1.66 | 22329861 | 0.03
9 | 473 | 96 | 2198500745 | 21.58 | 64316407 | 0.08
10 | 473 | 170 | 1745728752 | 17.13 | 361109507 | 0.45
11 | 473 | 315 | 346059472 | 3.40 | 621710946 | 0.77
12 | 473 | 480 | 318995391 | 3.13 | 692631372 | 0.86
13 | 473 | 1332 | 228300426 | 2.24 | 505810992 | 0.63
14 | 473 | 4572 | 417885907 | 4.10 | 446193312 | 0.55
15 | 473 | 8989 | 69602904 | 0.68 | 332055799 | 0.41
16 | 473 | 77792 | 877588966 | 8.61 | 241092971 | 0.30
17 | 473 | 101016 | 416842394 | 4.09 | 930288091 | 1.16
18 | 473 | 222680 | 704017256 | 6.91 | 9582455990 | 11.91
19 | 473 | 320247 | 59125467 | 0.58 | 6191656576 | 7.69
20 | 473 | 781250067 | 2352601485 | 23.09 | 60073580668 | 74.64
| 9465 | 781250067 | 10188743553 | 100.00 | 80484172794 | 100.00
SYSTEM 8:
bucket | entries | max_calls | total_time | pct_time | rows | pct_rows
--------+---------+-----------+------------+----------+-----------+----------
1 | 488 | 1 | 23279 | 0.01 | 386 | 0.00
2 | 488 | 1 | 23384 | 0.01 | 122 | 0.00
3 | 488 | 1 | 35873 | 0.02 | 22 | 0.00
4 | 488 | 1 | 23156 | 0.01 | 35 | 0.00
5 | 487 | 1 | 13197 | 0.01 | 317 | 0.00
6 | 487 | 1 | 766750 | 0.44 | 65 | 0.00
7 | 487 | 1 | 31692 | 0.02 | 393 | 0.00
8 | 487 | 1 | 18710 | 0.01 | 73103 | 0.02
9 | 487 | 1 | 30208 | 0.02 | 152 | 0.00
10 | 487 | 1 | 23425 | 0.01 | 14 | 0.00
11 | 487 | 1 | 27419 | 0.02 | 20 | 0.00
12 | 487 | 1 | 43374 | 0.02 | 3 | 0.00
13 | 487 | 1 | 18055 | 0.01 | 58 | 0.00
14 | 487 | 1 | 19688 | 0.01 | 6 | 0.00
15 | 487 | 1 | 22245 | 0.01 | 439 | 0.00
16 | 487 | 24 | 2039181 | 1.16 | 223493 | 0.05
17 | 487 | 768 | 25701471 | 14.62 | 884186 | 0.20
18 | 487 | 14121 | 53778863 | 30.60 | 2223665 | 0.50
19 | 487 | 164629 | 34266645 | 19.49 | 37279499 | 8.41
20 | 487 | 46517095 | 58866393 | 33.49 | 402612053 | 90.82
| 9744 | 46517095 | 175773006 | 100.00 | 443298031 | 100.00
System #7 is the particularly interesting one. Note that if this user had *not* increased their max to 10k, the SQL statements responsible for about 20% of their databases time would have been rolled off and lost from pg_stat_statements. On most systems the problem is actually a lot smaller than I expected, but there is still a case here where people might lose data from pg_stat_statements which they wouldn't want to lose. Might be worth a discussion about switching to sorting based on total_time instead of calls?
-Jeremy
---------- pg_stat_statements.max = 5000
SYSTEM 1:
bucket | entries | max_calls | total_time | pct_time | rows | pct_rows
--------+---------+-------------+-------------+----------+--------------+----------
1 | 243 | 4 | 2172 | 0.00 | 12395 | 0.00
2 | 243 | 8 | 2466 | 0.00 | 36148 | 0.00
3 | 243 | 15 | 6368 | 0.00 | 34711 | 0.00
4 | 243 | 28 | 17801 | 0.00 | 59143 | 0.00
5 | 243 | 52 | 23631 | 0.00 | 197337 | 0.00
6 | 243 | 126 | 119005 | 0.00 | 146798 | 0.00
7 | 243 | 275 | 184864 | 0.00 | 402160 | 0.00
8 | 243 | 648 | 672907 | 0.00 | 948613 | 0.00
9 | 243 | 1616 | 1175448 | 0.01 | 3011254 | 0.00
10 | 242 | 3775 | 803799 | 0.00 | 6308289 | 0.00
11 | 242 | 8572 | 3315890 | 0.02 | 13489707 | 0.00
12 | 242 | 19436 | 7747413 | 0.04 | 22958217 | 0.01
13 | 242 | 55933 | 8572104 | 0.05 | 45162385 | 0.01
14 | 242 | 168402 | 22795122 | 0.13 | 135961496 | 0.04
15 | 242 | 413909 | 62500891 | 0.35 | 352699202 | 0.11
16 | 242 | 744639 | 94332579 | 0.53 | 386606008 | 0.12
17 | 242 | 1374743 | 257049472 | 1.45 | 2085014682 | 0.64
18 | 242 | 3891776 | 840326001 | 4.75 | 2183808874 | 0.67
19 | 242 | 22378695 | 1544711644 | 8.73 | 10972242140 | 3.39
20 | 242 | 15589184235 | 14858568512 | 83.93 | 307346618022 | 94.99
| 4849 | 15589184235 | 17702928088 | 100.00 | 323555717581 | 100.00
SYSTEM 2:
bucket | entries | max_calls | total_time | pct_time | rows | pct_rows
--------+---------+-------------+------------+----------+---------------+----------
1 | 244 | 17 | 16191 | 0.00 | 48204 | 0.00
2 | 244 | 64 | 271114 | 0.00 | 363019 | 0.00
3 | 244 | 100 | 366725 | 0.00 | 671762 | 0.00
4 | 244 | 140 | 180140 | 0.00 | 1164382 | 0.00
5 | 244 | 186 | 608551 | 0.01 | 1768865 | 0.00
6 | 244 | 243 | 541205 | 0.01 | 2349195 | 0.00
7 | 244 | 309 | 456749 | 0.01 | 3152989 | 0.00
8 | 244 | 393 | 658530 | 0.01 | 4168022 | 0.00
9 | 244 | 510 | 1748446 | 0.02 | 5324083 | 0.00
10 | 244 | 660 | 837506 | 0.01 | 6175995 | 0.00
11 | 244 | 839 | 1238649 | 0.01 | 7998575 | 0.00
12 | 244 | 1161 | 1155261 | 0.01 | 8722566 | 0.00
13 | 244 | 1777 | 1590755 | 0.02 | 10255668 | 0.00
14 | 244 | 3757 | 1892540 | 0.02 | 12267192 | 0.00
15 | 244 | 7503 | 1970249 | 0.02 | 13806280 | 0.00
16 | 244 | 14022 | 2246406 | 0.02 | 9873244 | 0.00
17 | 244 | 27798 | 3710787 | 0.04 | 15258889 | 0.00
18 | 244 | 60297 | 6049492 | 0.07 | 27484995 | 0.00
19 | 243 | 263828 | 6925772 | 0.08 | 61324608 | 0.00
20 | 243 | 11359462345 | 9082897956 | 99.64 | 1914448979042 | 99.99
| 4878 | 11359462345 | 9115363026 | 100.00 | 1914641157575 | 100.00
---------- pg_stat_statements.max = 10000
SYSTEM 3:
bucket | entries | max_calls | total_time | pct_time | rows | pct_rows
--------+---------+-----------+------------+----------+-------------+----------
1 | 405 | 1 | 1903 | 0.00 | 24 | 0.00
2 | 405 | 1 | 11492 | 0.00 | 20 | 0.00
3 | 405 | 1 | 1755 | 0.00 | 61 | 0.00
4 | 405 | 1 | 1628 | 0.00 | 71 | 0.00
5 | 405 | 1 | 1758 | 0.00 | 16 | 0.00
6 | 405 | 1 | 1867 | 0.00 | 18 | 0.00
7 | 404 | 1 | 1596 | 0.00 | 23 | 0.00
8 | 404 | 1 | 1679 | 0.00 | 13 | 0.00
9 | 404 | 1 | 2984 | 0.00 | 23 | 0.00
10 | 404 | 1 | 6016 | 0.00 | 248 | 0.00
11 | 404 | 1 | 1714 | 0.00 | 49 | 0.00
12 | 404 | 1 | 1732 | 0.00 | 17 | 0.00
13 | 404 | 6 | 19308 | 0.01 | 1436 | 0.00
14 | 404 | 23 | 27046782 | 9.51 | 4181 | 0.00
15 | 404 | 90 | 1905408 | 0.67 | 18336 | 0.00
16 | 404 | 644 | 93061 | 0.03 | 111651 | 0.00
17 | 404 | 3083 | 12994763 | 4.57 | 516112 | 0.00
18 | 404 | 24168 | 234976 | 0.08 | 5065065 | 0.05
19 | 404 | 105507 | 9468647 | 3.33 | 24062919 | 0.22
20 | 404 | 749065295 | 232561858 | 81.78 | 10913252211 | 99.73
| 8086 | 749065295 | 284360925 | 100.00 | 10943032494 | 100.00
SYSTEM 4:
bucket | entries | max_calls | total_time | pct_time | rows | pct_rows
--------+---------+------------+------------+----------+------------+----------
1 | 346 | 1 | 19667 | 0.00 | 2 | 0.00
2 | 346 | 1 | 49980 | 0.01 | 4 | 0.00
3 | 346 | 1 | 34046 | 0.00 | 8 | 0.00
4 | 346 | 1 | 102305 | 0.01 | 43 | 0.00
5 | 346 | 1 | 51369 | 0.01 | 5 | 0.00
6 | 346 | 1 | 18724 | 0.00 | 5 | 0.00
7 | 346 | 1 | 32055 | 0.00 | 43 | 0.00
8 | 346 | 1 | 35607 | 0.01 | 45 | 0.00
9 | 346 | 1 | 16091 | 0.00 | 31 | 0.00
10 | 346 | 1 | 18696 | 0.00 | 6 | 0.00
11 | 346 | 1 | 88879 | 0.01 | 5 | 0.00
12 | 346 | 1 | 18936 | 0.00 | 9 | 0.00
13 | 346 | 1 | 2720 | 0.00 | 408 | 0.00
14 | 346 | 1 | 33465 | 0.00 | 13 | 0.00
15 | 346 | 1 | 22200 | 0.00 | 2 | 0.00
16 | 346 | 3 | 1516109 | 0.22 | 369 | 0.00
17 | 346 | 48 | 47541581 | 6.96 | 36564 | 0.00
18 | 346 | 13118 | 30152991 | 4.41 | 822077 | 0.01
19 | 346 | 151800 | 13622497 | 1.99 | 22931644 | 0.26
20 | 346 | 1830494680 | 589642951 | 86.33 | 8682168726 | 99.73
| 6920 | 1830494680 | 683020868 | 100.00 | 8705960009 | 100.00
SYSTEM 5:
bucket | entries | max_calls | total_time | pct_time | rows | pct_rows
1 | 475 | 9 | 893189 | 0.01 | 958040 | 0.00
2 | 475 | 19 | 2462391 | 0.02 | 6248719 | 0.03
3 | 475 | 34 | 20795485 | 0.15 | 61456170 | 0.27
4 | 475 | 54 | 192705939 | 1.38 | 29269715 | 0.13
5 | 475 | 76 | 20947539 | 0.15 | 62108105 | 0.27
6 | 475 | 105 | 30439360 | 0.22 | 29579780 | 0.13
7 | 475 | 149 | 112750582 | 0.81 | 12169241 | 0.05
8 | 475 | 197 | 59168134 | 0.42 | 23153432 | 0.10
9 | 475 | 233 | 270201714 | 1.93 | 47299193 | 0.21
10 | 475 | 344 | 49366939 | 0.35 | 26034858 | 0.11
11 | 474 | 480 | 147016160 | 1.05 | 25381678 | 0.11
12 | 474 | 722 | 128961149 | 0.92 | 29928478 | 0.13
13 | 474 | 1072 | 281782913 | 2.01 | 85346789 | 0.37
14 | 474 | 1832 | 72278183 | 0.52 | 70689440 | 0.31
15 | 474 | 2972 | 1476021946 | 10.55 | 196298836 | 0.86
16 | 474 | 5707 | 967959256 | 6.92 | 183873573 | 0.80
17 | 474 | 12876 | 1654604242 | 11.83 | 865935480 | 3.77
18 | 474 | 30402 | 3708901952 | 26.51 | 1213651635 | 5.29
19 | 474 | 250514 | 1028521943 | 7.35 | 7294711094 | 31.77
20 | 474 | 1095421646 | 3765557605 | 26.91 | 12693321192 | 55.29
[NULL] | 9490 | 1095421646 | 13991336620 | 100.00 | 22957415448 | 100.00
SYSTEM 6:
bucket | entries | max_calls | total_time | pct_time | rows | pct_rows
--------+---------+-----------+------------+----------+------------+----------
1 | 489 | 1 | 19089 | 0.01 | 227 | 0.00
2 | 489 | 1 | 17191 | 0.01 | 63 | 0.00
3 | 489 | 1 | 16191 | 0.01 | 3 | 0.00
4 | 489 | 1 | 19004 | 0.01 | 46 | 0.00
5 | 489 | 1 | 15455 | 0.01 | 2929 | 0.00
6 | 488 | 1 | 15646 | 0.01 | 3 | 0.00
7 | 488 | 1 | 14648 | 0.01 | 11 | 0.00
8 | 488 | 1 | 42245 | 0.02 | 4 | 0.00
9 | 488 | 1 | 25555 | 0.01 | 67 | 0.00
10 | 488 | 1 | 22782 | 0.01 | 3137 | 0.00
11 | 488 | 1 | 9012 | 0.00 | 110 | 0.00
12 | 488 | 1 | 22773 | 0.01 | 76 | 0.00
13 | 488 | 1 | 27693 | 0.01 | 3 | 0.00
14 | 488 | 3 | 1526935 | 0.65 | 6347 | 0.00
15 | 488 | 14 | 1563175 | 0.67 | 32264 | 0.00
16 | 488 | 65 | 2159331 | 0.92 | 175479 | 0.01
17 | 488 | 658 | 26080111 | 11.11 | 548347 | 0.02
18 | 488 | 15043 | 71774949 | 30.57 | 2366723 | 0.09
19 | 488 | 139639 | 35335687 | 15.05 | 44022110 | 1.72
20 | 488 | 80924635 | 96044962 | 40.91 | 2512784413 | 98.16
| 9765 | 80924635 | 234752432 | 100.00 | 2559942362 | 100.00
SYSTEM 7:
bucket | entries | max_calls | total_time | pct_time | rows | pct_rows
--------+---------+-----------+-------------+----------+-------------+----------
1 | 474 | 1 | 425784 | 0.00 | 361694 | 0.00
2 | 474 | 2 | 22314020 | 0.22 | 2696158 | 0.00
3 | 474 | 3 | 35609364 | 0.35 | 121351894 | 0.15
4 | 474 | 5 | 69937281 | 0.69 | 103883776 | 0.13
5 | 474 | 7 | 85452745 | 0.84 | 164374678 | 0.20
6 | 473 | 11 | 19180309 | 0.19 | 7020715 | 0.01
7 | 473 | 22 | 51312437 | 0.50 | 19251387 | 0.02
8 | 473 | 55 | 169262450 | 1.66 | 22329861 | 0.03
9 | 473 | 96 | 2198500745 | 21.58 | 64316407 | 0.08
10 | 473 | 170 | 1745728752 | 17.13 | 361109507 | 0.45
11 | 473 | 315 | 346059472 | 3.40 | 621710946 | 0.77
12 | 473 | 480 | 318995391 | 3.13 | 692631372 | 0.86
13 | 473 | 1332 | 228300426 | 2.24 | 505810992 | 0.63
14 | 473 | 4572 | 417885907 | 4.10 | 446193312 | 0.55
15 | 473 | 8989 | 69602904 | 0.68 | 332055799 | 0.41
16 | 473 | 77792 | 877588966 | 8.61 | 241092971 | 0.30
17 | 473 | 101016 | 416842394 | 4.09 | 930288091 | 1.16
18 | 473 | 222680 | 704017256 | 6.91 | 9582455990 | 11.91
19 | 473 | 320247 | 59125467 | 0.58 | 6191656576 | 7.69
20 | 473 | 781250067 | 2352601485 | 23.09 | 60073580668 | 74.64
| 9465 | 781250067 | 10188743553 | 100.00 | 80484172794 | 100.00
SYSTEM 8:
bucket | entries | max_calls | total_time | pct_time | rows | pct_rows
--------+---------+-----------+------------+----------+-----------+----------
1 | 488 | 1 | 23279 | 0.01 | 386 | 0.00
2 | 488 | 1 | 23384 | 0.01 | 122 | 0.00
3 | 488 | 1 | 35873 | 0.02 | 22 | 0.00
4 | 488 | 1 | 23156 | 0.01 | 35 | 0.00
5 | 487 | 1 | 13197 | 0.01 | 317 | 0.00
6 | 487 | 1 | 766750 | 0.44 | 65 | 0.00
7 | 487 | 1 | 31692 | 0.02 | 393 | 0.00
8 | 487 | 1 | 18710 | 0.01 | 73103 | 0.02
9 | 487 | 1 | 30208 | 0.02 | 152 | 0.00
10 | 487 | 1 | 23425 | 0.01 | 14 | 0.00
11 | 487 | 1 | 27419 | 0.02 | 20 | 0.00
12 | 487 | 1 | 43374 | 0.02 | 3 | 0.00
13 | 487 | 1 | 18055 | 0.01 | 58 | 0.00
14 | 487 | 1 | 19688 | 0.01 | 6 | 0.00
15 | 487 | 1 | 22245 | 0.01 | 439 | 0.00
16 | 487 | 24 | 2039181 | 1.16 | 223493 | 0.05
17 | 487 | 768 | 25701471 | 14.62 | 884186 | 0.20
18 | 487 | 14121 | 53778863 | 30.60 | 2223665 | 0.50
19 | 487 | 164629 | 34266645 | 19.49 | 37279499 | 8.41
20 | 487 | 46517095 | 58866393 | 33.49 | 402612053 | 90.82
| 9744 | 46517095 | 175773006 | 100.00 | 443298031 | 100.00
-- Jeremy Schneider Database Engineer Amazon Web Services
Hello, What about adding a log message for each entry_dealloc() execution? it could be usefull to start thinking increasing pg_stat_statements.max. is there any rule regarding the acceptable max value ? I'm playing in test with a 20 000 value without any problem, could it extendend to 100 000 ? In a system with pressure on numbers of pgss lines, and regular entry_dealloc() executions, low frequency entries are evicted firsts, and this should still be the same for new small queries with usage based on total_time. Maybe there is a third way, that would be to evict queries based on the "oldest modification time" ... This would garantee that latest queries would be kept long enough to be collected by aggregation tools. Regards PAscal -- Sent from: http://www.postgresql-archive.org/PostgreSQL-general-f1843780.html
On 10/5/18 13:47, Jeremy Schneider wrote: > In addition to Kim's results and my initial data, a handful of people > have forwarded results to me over the past few weeks. Here's what came > my way, aggregated and anonymized. One more from a 9.4 system with default 5000 entries. Note that this is a prod system but had only been gathering statements stats for about three and a half days - the admin enabled pg_stat_statements last week just to get stats for this email thread! (THANKS!!!) While only one system in this thread has shown significant time that would have rolled off, it is notable that the distribution of time across buckets is always fairly lumpy. In fact I think that a good number of systems have had more time in bucket 18 than bucket 19. bucket entries max_calls total_time pct_time rows pct_rows ------- -------- ---------- ----------- --------- --------- --------- 1 248 1 1165381 0.24 9307526 3.67 2 248 1 278185 0.06 1947097 0.77 3 248 1 3223514 0.67 17897919 7.05 4 248 1 8722415 1.83 811022 0.32 5 248 1 413639 0.09 2103781 0.83 6 247 1 437788 0.09 2614929 1.03 7 247 1 202555 0.04 2094212 0.83 8 247 1 121673 0.03 350547 0.14 9 247 1 9299903 1.95 63600921 25.06 10 247 1 3642767 0.76 40022469 15.77 11 247 1 263853 0.06 2226582 0.88 12 247 1 4155721 0.87 14599659 5.75 13 247 1 1093557 0.23 16616897 6.55 14 247 1 19171119 4.01 686112 0.27 15 247 4 6929727 1.45 3761442 1.48 16 247 14 396828 0.08 73952 0.03 17 247 61 1888290 0.4 112077 0.04 18 247 326 131894870 27.6 5701711 2.25 19 247 1692 7856099 1.64 1529441 0.6 20 247 8120695 276724834 57.91 67741576 26.69 Thank you to everyone who is sending stats back! If anyone else out there is reading this thread, it's never too late to add a little additional data to the pile. :) -Jeremy -- Jeremy Schneider Database Engineer Amazon Web Services
On 10/5/18 13:47, Jeremy Schneider wrote: > In addition to Kim's results and my initial data, a handful of people > have forwarded results to me over the past few weeks. Here's what came > my way, aggregated and anonymized. One more from a 9.4 system with default 5000 entries. Note that this is a prod system but had only been gathering statements stats for about three and a half days - the admin enabled pg_stat_statements last week just to get stats for this email thread! (THANKS!!!) While only one system in this thread has shown significant time that would have rolled off, it is notable that the distribution of time across buckets is always fairly lumpy. In fact I think that a good number of systems have had more time in bucket 18 than bucket 19. bucket entries max_calls total_time pct_time rows pct_rows ------- -------- ---------- ----------- --------- --------- --------- 1 248 1 1165381 0.24 9307526 3.67 2 248 1 278185 0.06 1947097 0.77 3 248 1 3223514 0.67 17897919 7.05 4 248 1 8722415 1.83 811022 0.32 5 248 1 413639 0.09 2103781 0.83 6 247 1 437788 0.09 2614929 1.03 7 247 1 202555 0.04 2094212 0.83 8 247 1 121673 0.03 350547 0.14 9 247 1 9299903 1.95 63600921 25.06 10 247 1 3642767 0.76 40022469 15.77 11 247 1 263853 0.06 2226582 0.88 12 247 1 4155721 0.87 14599659 5.75 13 247 1 1093557 0.23 16616897 6.55 14 247 1 19171119 4.01 686112 0.27 15 247 4 6929727 1.45 3761442 1.48 16 247 14 396828 0.08 73952 0.03 17 247 61 1888290 0.4 112077 0.04 18 247 326 131894870 27.6 5701711 2.25 19 247 1692 7856099 1.64 1529441 0.6 20 247 8120695 276724834 57.91 67741576 26.69 Thank you to everyone who is sending stats back! If anyone else out there is reading this thread, it's never too late to add a little additional data to the pile. :) -Jeremy -- Jeremy Schneider Database Engineer Amazon Web Services