祖传SQL脚本来啦
xiongcc约 17 分钟1前言
最近在忙着团队数据库运维能力的建设工作，故而写了两个脚本，一个脚本用于当出现生产问题时，快速采集相关信息用于事后诊断分析，比如perf/stack以及数据库自身的一些信息等，另外一个脚本是用于快速运维的，传入相关参数即可收集指定信息。
2一睹为快
让我们先瞅瞅第二个脚本，这个脚本的普适性较高，不依赖于特定环境，后续我会上传到 github，作为项目持续维护，不断更新这些"祖传"SQL。
脚本内容如下，会采集锁/检查点/年龄/索引/归档等信息，同时针对一些关键指标项会打印出 notice。
[postgres@xiongcc common_query_script]$ ./rscheck.sh --help
Description: The script is used to collect specified information
Usage:
./rscheck.sh lock dbname : lock wait queue and lock wait state
./rscheck.sh checkpoint dbname : background and checkpointer state
./rscheck.sh freeze dbname : database transaction id consuming state
./rscheck.sh replication dbname : streaming replication (physical) state
./rscheck.sh connections dbname : database connections and current query
./rscheck.sh index_bloat dbname : index bloat information (estimated value)
./rscheck.sh index_duplicate dbname : index duplicate information
./rscheck.sh index_low dbname : index low efficiency
./rscheck.sh index_state dbname : index detail information
./rscheck.sh long_transaction dbname : long transaction detail
./rscheck.sh relation_bloat dbname : relation bloat information (estimated value)
./rscheck.sh vacuum_state dbname : current vacuum progress information
./rscheck.sh index_create dbname : index create progress information
./rscheck.sh wal_archive dbname : wal archive progress information
./rscheck.sh wal_generate dbname : wal generate speed information
./rscheck.sh wait_event dbname : wait event and wait event type
./rscheck.sh --help or -h : print this help information
让我们先构造一点测试环境。
3锁
首先是锁，锁主要注意锁的数量是有上限的，因此假如一些操作超过了上限，就会提示out of shared memory，数据库就会崩溃重启，典型操作就是一次扫描太多的分区（不带分区裁剪）。
[postgres@xiongcc common_query_script]$ ./rscheck.sh lock postgres
waiter | holder | root_holder | path | deep
--------+--------+-------------+------------+------
2446 | 2400 | 2400 | 2446->2400 | 1
(1 row) PID | Lock Info | State
----------+-----------------------------------------------------------+------------------
2400 | Connect: postgres postgres local +| 17:49:51 started+
| SQL: insert into t1 values(1); +| waiting +
| Acquired: +| 00:03:06 ago
| RowExclusiveLock(relation,db:postgres;rel:t1) +|
| ExclusiveLock(virtualxid,3/356668) +|
| ExclusiveLock(transactionid,1997505) |
=> 2446 | Connect: postgres postgres local +| 17:50:05 started+
| SQL: alter table t1 add column info2 text; +| waiting +
| Waiting: AccessExclusiveLock(relation,db:postgres;rel:t1)+| 00:02:52 ago
| Acquired: +|
| ExclusiveLock(virtualxid,4/343032) +|
| ExclusiveLock(transactionid,1997506) |
(2 rows)
-[ RECORD 1 ]------+--------------------------------------
blocked_pid | 2446
blocked_user | postgres
blocked_duration | 00:02:52.77452
blocking_pid | 2400
blocking_user | postgres
blocking_duration | 00:03:06.778586
blocked_statement | alter table t1 add column info2 text;
blocking_statement | insert into t1 values(1);
- Description:
1. in default, max lock numbers in buffer equal max_connections * max_locks_per_transaction.pay attention to 'out of shared memory'
4检查点
检查点，background worker 应该是后台写的主力进程，因此假如你发现 backend_total_writen 这个值远大于其他指标，就要去观察是否 bgworker 太过于懒惰了，默认参数是十分保守的。比如我这个小破云主机，可以看到 backend_total_writen 远远大于其他值，说明后台进程为了在共享内存中找到容身之所，自己做了大量的刷脏这个累活，不难想象，吞吐率/RT等都会受到影响。
[postgres@xiongcc common_query_script]$ ./rscheck.sh checkpoint postgres
-[ RECORD 1 ]---------------+-----------------------
total_checkpoints | 10810
bgworker_total_writen | 31 GB
chkpointer_total_writen | 4011 MB
backend_total_writen | 225 GB
checkpoint_write_avg | 380 kB
minutes_between_checkpoints | 0.14436975043015726167
buffers_backend_fsync | 0- Description:
1. background worker and checkpointer should be should be the main force to flush dirty pages.
2. so if you find backend_total_writen is much larger than other values, it means that you need to adjust the relevant parameters of bgworker
5年龄
年龄，老生常谈了，分为惰性模式和急切模式，当心复制槽/长事务等
[postgres@xiongcc common_query_script]$ ./rscheck.sh freeze postgres
-[ RECORD 1 ]---------------+-----------
datname | template1
frozen_xid_age | 1996791
consumed_txid_pct | 0
remaining_txid | 2145486856
remaining_aggressive_vacuum | 198003209
-[ RECORD 2 ]---------------+-----------
datname | template0
frozen_xid_age | 1996791
consumed_txid_pct | 0
remaining_txid | 2145486856
remaining_aggressive_vacuum | 198003209
-[ RECORD 3 ]---------------+-----------
datname | postgres
frozen_xid_age | 1996791
consumed_txid_pct | 0
remaining_txid | 2145486856
remaining_aggressive_vacuum | 198003209
-[ RECORD 4 ]---------------+-----------
datname | phpabs
frozen_xid_age | 1996791
consumed_txid_pct | 0
remaining_txid | 2145486856
remaining_aggressive_vacuum | 198003209- Description:
1. datname contains the name of the database.
2. frozen_xid_age represents the age of the database-level frozen transaction ID. A higher value (for example, greater than autovacuum_freeze_max_age) means that the database needs attention.
3. consumed_txid_pct represents the percentage of the transaction ID against the maximum transaction ID limit (2 billion transaction IDs) for the database.
4. remaining_aggressive_vacuum represents the available transaction ID space before it reaches the aggressive VACUUM mode—how close the database is to the autovacuum_freeze_max_age value. A negative value means that there are some tables in the database that trigger an aggressive VACUUM operation due to the age of pg_class.relfrozentxid.
6连接数
连接数，小心连接风暴，可以考虑使用连接池收敛连接。
[postgres@xiongcc common_query_script]$ ./rscheck.sh connections postgres
datname | open | active | idle | idle_in_trans
----------+------+--------+------+---------------
| 9 | 3 | 0 | 1
postgres | 3 | 2 | 0 | 1
| 6 | 1 | 0 | 0
(3 rows) pid | age | usename | application_name | wait_event | wait_event_type | query
-------+-----------------+----------+------------------+---------------+-----------------+------------------------------------------
2446 | 00:10:33.181127 | postgres | psql | relation | Lock | alter table t1 add column info2 text;
2400 | 00:10:47.185224 | postgres | psql | ClientRead | Client | insert into t1 values(1);
31587 | 03:34:24.064726 | postgres | walreceiver | WalSenderMain | Activity | START_REPLICATION 20/74000000 TIMELINE 1
(3 rows)
7索引
索引分为索引膨胀/重复索引/低效索引等。
索引膨胀
说到索引膨胀，让我想起了上周①群里一位老铁问的问题，正是索引膨胀导致的，后续找个时间详细写一下。
提前预热的话各位可以参考 PostgreSQL中一例表膨胀小实验及相关思考
[postgres@xiongcc common_query_script]$ ./rscheck.sh index_bloat postgres
datname | nspname | relname | idxname | idx_scans | bloat_pct | table_mb | actual_mb | bloat_mb | total_mb
----------+---------+------------------+-----------------------+-----------+-----------+----------+-----------+----------+----------
postgres | public | pgbench_accounts | pgbench_accounts_pkey | 3378742 | 75 | 1280.742 | 191.313 | 581 | 772.313
postgres | public | t1 | t1_pkey | 0 | 55 | 651.047 | 96.227 | 118 | 214.227
postgres | public | t1 | t1_id_idx | 0 | 11 | 651.047 | 96.133 | 11 | 107.133
postgres | public | t1 | t1_id_idx1 | 0 | 11 | 651.047 | 96.133 | 11 | 107.133
postgres | public | pgbench_branches | pgbench_branches_pkey | 1230193 | 0 | 0.203 | 0.016 | 0 | 0.016
postgres | public | pgbench_tellers | pgbench_tellers_pkey | 1689369 | 67 | 0.281 | 0.094 | 0 | 0.094
(6 rows)- Description:
1. idx_scans: How many times the index is scanned, a lower value may indicate that the index is low efficiency, but pay attention to its functionality, such as a unique index
2. bloat_pct: bloat percentage
3. table_mb: relation size, exclude index
4. actual_mb: actual index size
5. bloat_mb: bloat index size
6. total_mb: total index size, include bloat size
低效索引
[postgres@xiongcc common_query_script]$ ./rscheck.sh index_low postgres
table_name | index_name | indisunique | idx_scans
------------------+-----------------------+-------------+-----------
pgbench_branches | pgbench_branches_pkey | t | 1230193
pgbench_tellers | pgbench_tellers_pkey | t | 1689369
pgbench_accounts | pgbench_accounts_pkey | t | 3378742
t1 | t1_pkey | t | 0
t1 | t1_id_idx | f | 0
t1 | t1_id_idx1 | f | 0
(6 rows)- Description:
1. idx_scans: How many times the index is scanned, a lower value may indicate that the index is low efficiency, but pay attention to its functionality, such as a unique index
重复索引
冗余索引见得还少吗？反正我见过一个列上8个索引的，注意是一个表上的一个列。
[postgres@xiongcc common_query_script]$ ./rscheck.sh index_duplicate postgres
size | idx1 | idx2 | idx3 | idx4
--------+---------+-----------+------------+------
428 MB | t1_pkey | t1_id_idx | t1_id_idx1 |
(1 row)
索引创建
在没有 pg_stat_progress_create_index 视图之前，创建索引的过程是个黑盒，完全抓瞎，你不知道是卡了，还是就是慢，好在后面版本提供了这个视图。
最后的描述我为了偷懒直接拷贝的官网内容，十分晦涩，看不懂的可以参照我之前的文章《索引创建的流程》
[postgres@xiongcc common_query_script]$ ./rscheck.sh index_create postgres
-[ RECORD 1 ]--------+-------------------------------
now | 2023-04-11 18:17:25.950179+08
started_at | 2023-04-11 18:17:25.086226+08
query_duration | 00:00:00.863953
pid_and_query | [2400] create index on t1(id);
index_name | -
table_name | t1
table_size | 651 MB
phase | building index: scanning table
wait_type_and_event |
current_locker_pid | 0
current_locker_query |
lockers_progress | N/A (0 of 0)
blocks_progress | 9.19% (7659 of 83334)
tuples_progress | N/A (0 of 0)
partitions_progress | N/A (0 of 0)-[ RECORD 1 ]--------+-------------------------------
now | 2023-04-11 18:17:27.113253+08
started_at | 2023-04-11 18:17:25.086226+08
query_duration | 00:00:02.027027
pid_and_query | [2400] create index on t1(id);
index_name | -
table_name | t1
table_size | 651 MB
phase | building index: scanning table
wait_type_and_event |
current_locker_pid | 0
current_locker_query |
lockers_progress | N/A (0 of 0)
blocks_progress | 20.11% (16758 of 83334)
tuples_progress | N/A (0 of 0)
partitions_progress | N/A (0 of 0)
-[ RECORD 1 ]--------+-------------------------------
now | 2023-04-11 18:17:28.2297+08
started_at | 2023-04-11 18:17:25.086226+08
query_duration | 00:00:03.143474
pid_and_query | [2400] create index on t1(id);
index_name | -
table_name | t1
table_size | 651 MB
phase | building index: scanning table
wait_type_and_event |
current_locker_pid | 0
current_locker_query |
lockers_progress | N/A (0 of 0)
blocks_progress | 30.05% (25039 of 83334)
tuples_progress | N/A (0 of 0)
partitions_progress | N/A (0 of 0)
-[ RECORD 1 ]--------+-------------------------------
now | 2023-04-11 18:17:29.351647+08
started_at | 2023-04-11 18:17:25.086226+08
query_duration | 00:00:04.265421
pid_and_query | [2400] create index on t1(id);
index_name | -
table_name | t1
table_size | 651 MB
phase | building index: scanning table
wait_type_and_event |
current_locker_pid | 0
current_locker_query |
lockers_progress | N/A (0 of 0)
blocks_progress | 43.41% (36174 of 83334)
tuples_progress | N/A (0 of 0)
partitions_progress | N/A (0 of 0)
-[ RECORD 1 ]--------+-------------------------------
now | 2023-04-11 18:17:31.284616+08
started_at | 2023-04-11 18:17:25.086226+08
query_duration | 00:00:06.19839
pid_and_query | [2400] create index on t1(id);
index_name | -
table_name | t1
table_size | 651 MB
phase | building index: scanning table
wait_type_and_event |
current_locker_pid | 0
current_locker_query |
lockers_progress | N/A (0 of 0)
blocks_progress | 94.12% (78438 of 83334)
tuples_progress | N/A (0 of 0)
partitions_progress | N/A (0 of 0)
- Description:
1. initializing: CREATE INDEX or REINDEX is preparing to create the index. This phase is expected to be very brief.
2. waiting for writers before build: CREATE INDEX CONCURRENTLY or REINDEX CONCURRENTLY is waiting for transactions with write locks that can potentially see the table to finish. This phase is skipped when not in concurrent mode. Columns lockers_total, lockers_done and current_locker_pid contain the progress information for this phase.
3. building index: The index is being built by the access method-specific code. In this phase, access methods that support progress reporting fill in their own progress data, and the subphase is indicated in this column. Typically, blocks_total and blocks_done will contain progress data, as well as potentially tuples_total and tuples_done.
4. waiting for writers before validation: CREATE INDEX CONCURRENTLY or REINDEX CONCURRENTLY is waiting for transactions with write locks that can potentially write into the table to finish. This phase is skipped when not in concurrent mode. Columns lockers_total, lockers_done and current_locker_pid contain the progress information for this phase.
5. index validation: scanning index: CREATE INDEX CONCURRENTLY is scanning the index searching for tuples that need to be validated. This phase is skipped when not in concurrent mode. Columns blocks_total (set to the total size of the index) and blocks_done contain the progress information for this phase.
6. index validation: sorting tuples CREATE INDEX CONCURRENTLY is sorting the output of the index scanning phase.
7. index validation: scanning table CREATE INDEX CONCURRENTLY is scanning the table to validate the index tuples collected in the previous two phases. This phase is skipped when not in concurrent mode. Columns blocks_total (set to the total size of the table) and blocks_done contain the progress information for this phase.
8. waiting for old snapshots CREATE INDEX CONCURRENTLY or REINDEX CONCURRENTLY is waiting for transactions that can potentially see the table to release their snapshots. This phase is skipped when not in concurrent mode. Columns lockers_total, lockers_done and current_locker_pid contain the progress information for this phase.
9. waiting for readers before marking dead: REINDEX CONCURRENTLY is waiting for transactions with read locks on the table to finish, before marking the old index dead. This phase is skipped when not in concurrent mode. Columns lockers_total, lockers_done and current_locker_pid contain the progress information for this phase.
10. waiting for readers before dropping: REINDEX CONCURRENTLY is waiting for transactions with read locks on the table to finish, before dropping the old index. This phase is skipped when not in concurrent mode. Columns lockers_total, lockers_done and current_locker_pid contain the progress information for this phase.
8长事务
数据库杀手——长事务，我还特意列举了长事务的种种罪恶。
[postgres@xiongcc common_query_script]$ ./rscheck.sh long_transaction postgres
state | wait_event | wait_event_type | client_addr | client_port | application_name | duration | query
---------------------+------------+-----------------+-------------+-------------+------------------+-----------------+---------------------------
idle in transaction | ClientRead | Client | | -1 | psql | 00:20:13.759949 | insert into t1 values(1);
(1 row)- Description:
1. long transaction is dbkiller,pay attention!
2. it will prevent vacuum cleaning and cause table bloat
3. block the use of the index (the index cannot be used after creation), will make the problem phenomenon very confusing
4. if there are sub-transactions, combined with long transactions, it is easy to cause a sharp drop in performance
5. age can only be reduced to the earliest long transaction that exists in the system, that is, min (pg_stat_activity.(backend_xid, backend_xmin))
6. under logical decoding, long transactions will block the creation of replication slots. In fact, it is to push to a consistent point to start parsing, so it will block logical replication, CDC, etc.
7. under logical decoding, large transactions will cause WAL logs to accumulate
8. long transactions will cause partial accumulation of WAL logs in the standby database of stream replication
9表膨胀
表膨胀老熟人了，为了方便，我还把 OldestXmin 这个罪魁祸首给查了出来。
[postgres@xiongcc common_query_script]$ ./rscheck.sh relation_bloat postgres
databasename | schemaname | tablename | can_estimate | est_rows | pct_bloat | mb_bloat | table_mb
--------------+------------+-----------+--------------+----------+-----------+----------+----------
postgres | public | t1 | t | 5000000 | 50 | 326.00 | 651.047
(1 row)- Description:
1. pct_bloat: bloat percentage
2. mb_bloat: bloat table size
3. table_mb: total table size, include bloat size
Oldest xmin will block vacuum process,pay attention:
-[ RECORD 1 ]+------------------------------
src | pg_stat_activity
xact_start | 2023-04-11 17:49:50.015638+08
usename | postgres
datname | postgres
query | insert into t1 values(1);
backend_xid | 1997505
backend_xmin |
10vacuum
vacuum会以一个可视化的形式打印出来，可以参照之前的 visualizing vacuum 文章。
[postgres@xiongcc common_query_script]$ ./rscheck.sh vacuum_state postgres
pid | duration | waiting | mode | database | table | phase | table_size | total_size | scanned | vacuumed | scanned_pct | vacuumed_pct | index_vacuum_count | dead_pct
------+---------------+------------+------+----------+------------------+---------------+------------+------------+---------+----------+-------------+--------------+--------------------+----------
2400 | 00:00:00.4614 | IO.WALSync | user | postgres | pgbench_accounts | scanning heap | 1281 MB | 2054 MB | 18 MB | 0 bytes | 1.4 | 0.0 | 0 | 0.1
(1 row) pid | duration | waiting | mode | database | table | phase | table_size | total_size | scanned | vacuumed | scanned_pct | vacuumed_pct | index_vacuum_count | dead_pct
------+-----------------+------------+------+----------+------------------+---------------+------------+------------+---------+----------+-------------+--------------+--------------------+----------
2400 | 00:00:01.507505 | IO.WALSync | user | postgres | pgbench_accounts | scanning heap | 1281 MB | 2054 MB | 56 MB | 0 bytes | 4.4 | 0.0 | 0 | 0.2
(1 row)
pid | duration | waiting | mode | database | table | phase | table_size | total_size | scanned | vacuumed | scanned_pct | vacuumed_pct | index_vacuum_count | dead_pct
------+-----------------+------------+------+----------+------------------+---------------+------------+------------+---------+----------+-------------+--------------+--------------------+----------
2400 | 00:00:02.551887 | IO.WALSync | user | postgres | pgbench_accounts | scanning heap | 1281 MB | 2054 MB | 96 MB | 0 bytes | 7.5 | 0.0 | 0 | 0.4
(1 row)
pid | duration | waiting | mode | database | table | phase | table_size | total_size | scanned | vacuumed | scanned_pct | vacuumed_pct | index_vacuum_count | dead_pct
------+-----------------+------------+------+----------+------------------+---------------+------------+------------+---------+----------+-------------+--------------+--------------------+----------
2400 | 00:00:03.587567 | IO.WALSync | user | postgres | pgbench_accounts | scanning heap | 1281 MB | 2054 MB | 131 MB | 0 bytes | 10.2 | 0.0 | 0 | 0.5
(1 row)
pid | duration | waiting | mode | database | table | phase | table_size | total_size | scanned | vacuumed | scanned_pct | vacuumed_pct | index_vacuum_count | dead_pct
------+-----------------+------------+------+----------+------------------+---------------+------------+------------+---------+----------+-------------+--------------+--------------------+----------
2400 | 00:00:05.132032 | IO.WALSync | user | postgres | pgbench_accounts | scanning heap | 1281 MB | 2054 MB | 156 MB | 0 bytes | 12.2 | 0.0 | 0 | 0.6
(1 row)
- Description:
1. phase – internally, vacuum has several stages and this field shows the exact phase it is in at the moment.
2. heap_blks_total, heap_blks_scanned, heap_blks_vacuumed – are about relation’s size (in blocks) and how many blocks have already been processed. These are the main values that help to estimate progress of the running a vacuum.
3. max_dead_tuples, num_dead_tuples – these values are about dead tuples storage which is based on the autovacuum_work_mem (or maintenance_work_mem if previous isn’t set). When there is no free space in the dead tuples storage, vacuum starts processing indexes and it might happen multiple times. Each time when this occurs, the index_vacuum_count is incremented.
11WAL日志
归档
我统计了 current_archived_wals_per_second，用于大概衡量归档的速度。
[postgres@xiongcc common_query_script]$ ./rscheck.sh wal_archive postgres
-[ RECORD 1 ]--------------------+-----------------------------
archived_count | 0
last_archived_wal |
last_archived_time |
failed_count | 0
last_failed_wal |
last_failed_time |
stats_reset | 2023-02-15 12:00:44.46167+08
is_archiving | f
current_archived_wals_per_second | 0.000000000000000000000000
生成速度
[postgres@xiongcc common_query_script]$ ./rscheck.sh wal_generate postgres
-[ RECORD 1 ]-+---------
day_id | 20230411
wal_num_all | 38
wal_num_00_01 | 0
wal_num_01_02 | 0
wal_num_02_03 | 0
wal_num_03_04 | 0
wal_num_04_05 | 0
wal_num_05_06 | 0
wal_num_06_07 | 0
wal_num_07_08 | 0
wal_num_08_09 | 0
wal_num_09_10 | 0
wal_num_10_11 | 0
wal_num_11_12 | 0
wal_num_12_13 | 0
wal_num_13_14 | 0
wal_num_14_15 | 0
wal_num_15_16 | 0
wal_num_16_17 | 0
wal_num_17_18 | 0
wal_num_18_19 | 38
wal_num_19_20 | 0
wal_num_20_21 | 0
wal_num_21_22 | 0
wal_num_22_23 | 0
wal_num_23_24 | 0-[ RECORD 1 ]----+-----------------------------
wal_records | 1096864868
wal_fpi | 8607881
wal_bytes | 137793359234
wal_buffers_full | 7084314
wal_write | 8247237
wal_sync | 1155748
wal_write_time | 0
wal_sync_time | 0
stats_reset | 2023-02-15 12:00:44.46167+08
12小结
That's all. 拭目以待。