Objective:
Postgresql: How to collect the performance metrics for a sql
Dears,
For this excercise..
1) we will need postgresql contrib (core extension) installed in the linux server.
Installed:
postgresql14-contrib.x86_64 0:14.7-1PGDG.rhel7
2) Postgresql parameter shared_preload_libraries needs to be set to pg_stat_statements (in case you need auto_explain, please set that as well, this comes from same contrib package only).
postgres=# show shared_preload_libraries;
shared_preload_libraries
--------------------------
(1 row)
postgres=# alter system set shared_preload_libraries='pg_stat_statements';
ALTER SYSTEM
postgres=#
postgresql restart
postgres=# show shared_preload_libraries;
shared_preload_libraries
--------------------------
(1 row)
postgres=# alter system set shared_preload_libraries='pg_stat_statements';
ALTER SYSTEM
postgres=#
postgresql restart
3) An extension for pg_stat_statements needs to be created as well (for auto_explain just "load 'auto_explain';" is good enought)
postgres=# create extension pg_stat_statements;
CREATE EXTENSION
postgres=# create extension pg_stat_statements;
CREATE EXTENSION
Test routine:
postgresql version: 14
shared_buffer current size: 128MB (default)
create table:
create table test_shrbuf as
with t as
(
select generate_series(0,1000000) lvl
)
select t.lvl
,(mod(t.lvl,100)+date '1/1/2022') as dob
,lpad('A',(mod(t.lvl,20)+(20-mod(t.lvl,20))),chr(65+mod((t.lvl/26),26))) as hosptl
,substr(md5(random()::text),15) as fn
,substr(md5(random()::text),15) as ln
,'UKCO'||chr(65+mod(t.lvl,26))||chr(65+mod((t.lvl/26),26)) as POSCODE
from t;
Table stats after load:
postgres=# \dt+
List of relations
Schema | Name | Type | Owner | Persistence | Access method | Size | Description
--------+-------------+-------+----------+-------------+---------------+--------+-------------
public | test_shrbuf | table | postgres | permanent | heap | 104 MB |
(1 row)
postgres=# select * from pg_class where relname='test_shrbuf';
-[ RECORD 1 ]-------+-------------
oid | 16411
relname | test_shrbuf
relnamespace | 2200
reltype | 16413
reloftype | 0
relowner | 10
relam | 2
relfilenode | 16411
reltablespace | 0
relpages | 13334
reltuples | 1.000001e+06
relallvisible | 13334
reltoastrelid | 16414
relhasindex | f
relisshared | f
relpersistence | p
relkind | r
relnatts | 6
relchecks | 0
relhasrules | f
relhastriggers | f
relhassubclass | f
relrowsecurity | f
relforcerowsecurity | f
relispopulated | t
relreplident | d
relispartition | f
relrewrite | 0
relfrozenxid | 200807
relminmxid | 1
relacl |
reloptions |
relpartbound |
Time: 0.608 ms
postgres=# select * from pg_stat_user_tables where relname='test_shrbuf';
-[ RECORD 1 ]-------+------------------------------
relid | 16411
schemaname | public
relname | test_shrbuf
seq_scan | 0
seq_tup_read | 0
idx_scan |
idx_tup_fetch |
n_tup_ins | 1000001
n_tup_upd | 0
n_tup_del | 0
n_tup_hot_upd | 0
n_live_tup | 1000001
n_dead_tup | 0
n_mod_since_analyze | 0
n_ins_since_vacuum | 0
last_vacuum |
last_autovacuum | 2023-04-01 20:41:25.488159+01
last_analyze |
last_autoanalyze | 2023-04-01 20:41:26.594851+01
vacuum_count | 0
autovacuum_count | 1
analyze_count | 0
autoanalyze_count | 1
Time: 27.018 ms
postgres=#
Basic column stats:
postgres=# select attname,avg_width,n_distinct,correlation from pg_stats where tablename='test_shrbuf' order by 1;
attname | avg_width | n_distinct | correlation
---------+-----------+------------+----------------
dob | 4 | 100 | 0.0115944
fn | 19 | -1 | 0.007690633
hosptl | 21 | 26 | 0.035581134
ln | 19 | -1 | -0.00087328884
lvl | 4 | -1 | 1
poscode | 7 | 676 | -0.0018468185
(6 rows)
Time: 2.729 ms
postgres=#
If we look above, the hosptl or poscode or dob cant be a btree index due to their low cardinality factor.
So we will implement btree index on lvl column.
create index test_shrbuf_idx_lvl on test_shrbuf(lvl);
postgres=# \d+ test_shrbuf
Table "public.test_shrbuf"
Column | Type | Collation | Nullable | Default | Storage | Compression | Stats target | Description
---------+---------+-----------+----------+---------+----------+-------------+--------------+-------------
lvl | integer | | | | plain | | |
dob | date | | | | plain | | |
hosptl | text | | | | extended | | |
fn | text | | | | extended | | |
ln | text | | | | extended | | |
poscode | text | | | | extended | | |
Indexes:
"test_shrbuf_idx_lvl" btree (lvl)
Access method: heap
postgres=#
postgres=# \d+ test_shrbuf_idx_lvl
Index "public.test_shrbuf_idx_lvl"
Column | Type | Key? | Definition | Storage | Stats target
--------+---------+------+------------+---------+--------------
lvl | integer | yes | lvl | plain |
btree, for table "public.test_shrbuf"
postgres=#
so a btree index is created & we are ready to test the queries.
To assess performance metrics for a query....
We need to use
a.pg_stat_user_tables (how many seq and index read)
b.pg_stat_user_indexes (how many index read and index tuples and index fetches)
c.pg_stat_statements (you can see how many blocks are read from disk here)
For ex.
>>>>>>>>> Before:
postgres=# select * from pg_stat_user_tables;
-[ RECORD 1 ]-------+------------------------------
relid | 16411
schemaname | public
relname | test_shrbuf
seq_scan | 11
seq_tup_read | 4000004
idx_scan | 2
idx_tup_fetch | 1
n_tup_ins | 1000001
n_tup_upd | 0
n_tup_del | 0
n_tup_hot_upd | 0
n_live_tup | 1000001
n_dead_tup | 0
n_mod_since_analyze | 0
n_ins_since_vacuum | 0
last_vacuum |
last_autovacuum | 2023-04-01 20:41:25.488159+01
last_analyze |
last_autoanalyze | 2023-04-01 20:41:26.594851+01
vacuum_count | 0
autovacuum_count | 1
analyze_count | 0
autoanalyze_count | 1
postgres=# select * from pg_stat_user_indexes;
-[ RECORD 1 ]-+--------------------
relid | 16411
indexrelid | 16418
schemaname | public
relname | test_shrbuf
indexrelname | test_shrbuf_idx_lvl
idx_scan | 2
idx_tup_read | 1
idx_tup_fetch | 1
postgres=#
postgres=# select * from pg_stat_statements where query like '%test_shrbuf%';
-[ RECORD 1 ]-------+-----------------------------------------------------------------
userid | 10
dbid | 14486
toplevel | t
queryid | 5107427994153183476
query | explain analyze select * from test_shrbuf where ln='ccc'
plans | 0
total_plan_time | 0
min_plan_time | 0
max_plan_time | 0
mean_plan_time | 0
stddev_plan_time | 0
calls | 1
total_exec_time | 349.189455
min_exec_time | 349.189455
max_exec_time | 349.189455
mean_exec_time | 349.189455
stddev_exec_time | 0
rows | 0
shared_blks_hit | 70
shared_blks_read | 13339
shared_blks_dirtied | 0
shared_blks_written | 0
local_blks_hit | 0
local_blks_read | 0
local_blks_dirtied | 0
local_blks_written | 0
temp_blks_read | 0
temp_blks_written | 0
blk_read_time | 0
blk_write_time | 0
wal_records | 1
wal_fpi | 0
wal_bytes | 108
-[ RECORD 2 ]-------+-----------------------------------------------------------------
userid | 10
dbid | 14486
toplevel | t
queryid | 7139240640460061921
query | explain analyze select * from test_shrbuf where poscode='zz'
plans | 0
total_plan_time | 0
min_plan_time | 0
max_plan_time | 0
mean_plan_time | 0
stddev_plan_time | 0
calls | 1
total_exec_time | 322.161787
min_exec_time | 322.161787
max_exec_time | 322.161787
mean_exec_time | 322.161787
stddev_exec_time | 0
rows | 0
shared_blks_hit | 267
shared_blks_read | 13142
shared_blks_dirtied | 0
shared_blks_written | 0
local_blks_hit | 0
local_blks_read | 0
local_blks_dirtied | 0
local_blks_written | 0
temp_blks_read | 0
temp_blks_written | 0
blk_read_time | 0
blk_write_time | 0
wal_records | 0
wal_fpi | 0
wal_bytes | 0
-[ RECORD 3 ]-------+-----------------------------------------------------------------
userid | 10
dbid | 14486
toplevel | t
queryid | 7966750236604292602
query | explain analyze select * from test_shrbuf where dob='2023-01-02'
plans | 0
total_plan_time | 0
min_plan_time | 0
max_plan_time | 0
mean_plan_time | 0
stddev_plan_time | 0
calls | 1
total_exec_time | 278.342412
min_exec_time | 278.342412
max_exec_time | 278.342412
mean_exec_time | 278.342412
stddev_exec_time | 0
rows | 0
shared_blks_hit | 100
shared_blks_read | 13240
shared_blks_dirtied | 0
shared_blks_written | 0
local_blks_hit | 0
local_blks_read | 0
local_blks_dirtied | 0
local_blks_written | 0
temp_blks_read | 0
temp_blks_written | 0
blk_read_time | 0
blk_write_time | 0
wal_records | 0
wal_fpi | 0
wal_bytes | 0
postgres=#
>>>>>>>>> QUERY [the below command will explain and run the query as well - will show you estimate and actual results]
postgres=# explain analyze select * from test_shrbuf where poscode='ooo';
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------
-----
Gather (cost=1000.00..19689.74 rows=1474 width=74) (actual time=319.964..320.042 rows=0 loops=1)
Workers Planned: 2
Workers Launched: 2
-> Parallel Seq Scan on test_shrbuf (cost=0.00..18542.34 rows=614 width=74) (actual time=297.092..297.093 rows=0 loop
s=3)
Filter: (poscode = 'ooo'::text)
Rows Removed by Filter: 333334
Planning Time: 0.065 ms
Execution Time: 320.060 ms
(8 rows)
postgres=#
>>>>>>>>> After:
postgres=# select * from pg_stat_user_tables;
-[ RECORD 1 ]-------+------------------------------
relid | 16411
schemaname | public
relname | test_shrbuf
seq_scan | 14
seq_tup_read | 5000005 <<<<< 1000000 more
idx_scan | 2
idx_tup_fetch | 1
n_tup_ins | 1000001
n_tup_upd | 0
n_tup_del | 0
n_tup_hot_upd | 0
n_live_tup | 1000001
n_dead_tup | 0
n_mod_since_analyze | 0
n_ins_since_vacuum | 0
last_vacuum |
last_autovacuum | 2023-04-01 20:41:25.488159+01
last_analyze |
last_autoanalyze | 2023-04-01 20:41:26.594851+01
vacuum_count | 0
autovacuum_count | 1
analyze_count | 0
autoanalyze_count | 1
postgres=# select * from pg_stat_user_indexes;
-[ RECORD 1 ]-+--------------------
relid | 16411
indexrelid | 16418
schemaname | public
relname | test_shrbuf
indexrelname | test_shrbuf_idx_lvl
idx_scan | 2 <<< No change
idx_tup_read | 1
idx_tup_fetch | 1
postgres=#
postgres=# select * from pg_stat_statements where query like '%test_shrbuf%';
-[ RECORD 1 ]-------+-----------------------------------------------------------------
userid | 10
dbid | 14486
toplevel | t
queryid | 5107427994153183476
query | explain analyze select * from test_shrbuf where ln='ccc'
plans | 0
total_plan_time | 0
min_plan_time | 0
max_plan_time | 0
mean_plan_time | 0
stddev_plan_time | 0
calls | 1
total_exec_time | 349.189455
min_exec_time | 349.189455
max_exec_time | 349.189455
mean_exec_time | 349.189455
stddev_exec_time | 0
rows | 0
shared_blks_hit | 70
shared_blks_read | 13339
shared_blks_dirtied | 0
shared_blks_written | 0
local_blks_hit | 0
local_blks_read | 0
local_blks_dirtied | 0
local_blks_written | 0
temp_blks_read | 0
temp_blks_written | 0
blk_read_time | 0
blk_write_time | 0
wal_records | 1
wal_fpi | 0
wal_bytes | 108
-[ RECORD 2 ]-------+-----------------------------------------------------------------
userid | 10
dbid | 14486
toplevel | t
queryid | 7139240640460061921
query | explain analyze select * from test_shrbuf where poscode='zz'
plans | 0
total_plan_time | 0
min_plan_time | 0
max_plan_time | 0
mean_plan_time | 0
stddev_plan_time | 0
calls | 1
total_exec_time | 322.161787
min_exec_time | 322.161787
max_exec_time | 322.161787
mean_exec_time | 322.161787
stddev_exec_time | 0
rows | 0
shared_blks_hit | 267
shared_blks_read | 13142
shared_blks_dirtied | 0
shared_blks_written | 0
local_blks_hit | 0
local_blks_read | 0
local_blks_dirtied | 0
local_blks_written | 0
temp_blks_read | 0
temp_blks_written | 0
blk_read_time | 0
blk_write_time | 0
wal_records | 0
wal_fpi | 0
wal_bytes | 0
-[ RECORD 3 ]-------+-----------------------------------------------------------------
userid | 10
dbid | 14486
toplevel | t
queryid | 7966750236604292602
query | explain analyze select * from test_shrbuf where dob='2023-01-02'
plans | 0
total_plan_time | 0
min_plan_time | 0
max_plan_time | 0
mean_plan_time | 0
stddev_plan_time | 0
calls | 1
total_exec_time | 278.342412
min_exec_time | 278.342412
max_exec_time | 278.342412
mean_exec_time | 278.342412
stddev_exec_time | 0
rows | 0
shared_blks_hit | 100
shared_blks_read | 13240
shared_blks_dirtied | 0
shared_blks_written | 0
local_blks_hit | 0
local_blks_read | 0
local_blks_dirtied | 0
local_blks_written | 0
temp_blks_read | 0
temp_blks_written | 0
blk_read_time | 0
blk_write_time | 0
wal_records | 0
wal_fpi | 0
wal_bytes | 0
-[ RECORD 4 ]-------+-----------------------------------------------------------------
userid | 10
dbid | 14486
toplevel | t
queryid | -1420991365901836770
query | explain analyze select * from test_shrbuf where poscode='ooo' <<<<<< our latest statement
plans | 0
total_plan_time | 0
min_plan_time | 0
max_plan_time | 0
mean_plan_time | 0
stddev_plan_time | 0
calls | 1
total_exec_time | 320.199783
min_exec_time | 320.199783
max_exec_time | 320.199783
mean_exec_time | 320.199783
stddev_exec_time | 0
rows | 0
shared_blks_hit | 288 <<< a bit improved, still not all the blocks are kept in memory
shared_blks_read | 13046 <<< these many blocks need to be pulled from disk
shared_blks_dirtied | 0
shared_blks_written | 0
local_blks_hit | 0
local_blks_read | 0
local_blks_dirtied | 0
local_blks_written | 0
temp_blks_read | 0
temp_blks_written | 0
blk_read_time | 0
blk_write_time | 0
wal_records | 0
wal_fpi | 0
wal_bytes | 0
postgres=#
postgres=# select queryid,query,shared_blks_hit,shared_blks_read from pg_stat_statements where query like '%test_shrbuf%' order by queryid;
-[ RECORD 1 ]----+-----------------------------------------------------------------
queryid | -1420991365901836770
query | explain analyze select * from test_shrbuf where poscode='ooo'
shared_blks_hit | 288 <<< see the shared_block_hit value improving each time with a query on the table
shared_blks_read | 13046
-[ RECORD 2 ]----+-----------------------------------------------------------------
queryid | 5107427994153183476
query | explain analyze select * from test_shrbuf where ln='ccc'
shared_blks_hit | 70 <<< started from here
shared_blks_read | 13339
-[ RECORD 3 ]----+-----------------------------------------------------------------
queryid | 7139240640460061921
query | explain analyze select * from test_shrbuf where poscode='zz'
shared_blks_hit | 267
shared_blks_read | 13142
-[ RECORD 4 ]----+-----------------------------------------------------------------
queryid | 7966750236604292602
query | explain analyze select * from test_shrbuf where dob='2023-01-02'
shared_blks_hit | 100
shared_blks_read | 13240
postgres=#
We will continue with more postgresql performance monitoring blog in future.
Thanks
No comments:
Post a Comment