PostgreSQL (慢SQL|数据库整体变慢|性能抖动) 数据库性能分析与优化方法

标签：rows PostgreSQL log 数据库 time tbl SQL 性能

背景

本文将介绍三种数据库变慢场景的分析与优化方法.

1、已经定位出的特定慢SQL
2、整个数据库实例(几乎所有SQL)变慢, 或者某些时候整个数据库实例大面积SQL变慢(大面积抖动)
3、某些正常情况下很快的SQL偶尔会变慢(抖动)

在优化之前

“治未病”的概念最早出现于《黄帝内经》,在《素问·四气调神大论》中提出：“是故圣人不治已病治未病,不治已乱治未乱,此之谓也。夫病已成而后药之,乱已成而后治之,譬犹渴而穿井,斗而铸锥,不亦晚乎”，就生动地指出了“治未病”的重要意义。

数据库优化固然重要, 但这是治已病, 未病则更加重要. 未病建议参考:

一、单一慢SQL优化

单一SQL慢, 比较容易解决, 从执行计划入手即可, 是否执行计划不正确, 是否索引未创建或不合理, 是否需要改写SQL, 是否有膨胀, 是否存在业务逻辑导致的长时间锁冲突, 是否SQL过于复杂需要固定执行计划或者采用更高级的优化器.

常用分析工具与方法:

explain, 分析执行计划
索引推荐
检查膨胀
perf, 分析单条SQL(或函数)执行时的代码瓶颈
锁等待分析
查询其他会话中正在运行的SQL memory context
show 其他会话中正在运行的SQL的执行计划
动态优化
指定、固定、篡改执行计划
数据库存储组织、数据库索引组织、优化器算法、数据扫描方法等原理

例子, 查询所有传感器上报数据的最新值:

create unlogged table tbl_log (gid int, info text, crt_time timestamp);  
  
insert into tbl_log select random()*10, md5(random()::Text), clock_timestamp() from generate_series(1,5000000);  
  
select gid,info,crt_Time from   
  (select *, row_number() over (partition by gid order by crt_time desc) as rn from tbl_log) t  
where rn=1;   
  
 gid |               info               |          crt_time            
-----+----------------------------------+----------------------------  
   0 | 144ccff07b812d0ca5252ae8cbc2ad50 | 2022-08-23 14:59:59.531316  
   1 | 22fb4e6bb2daa15fcb8b00358bb4f3ad | 2022-08-23 14:59:59.531342  
   2 | 43761591e939309f1bb9e2b94f642e6d | 2022-08-23 14:59:59.531356  
   3 | 1751a3a7884685ec2c16926b4e2ad607 | 2022-08-23 14:59:59.531341  
   4 | 5df93803d19bf3a6bd19b7d017757bed | 2022-08-23 14:59:59.531348  
   5 | c11384fa2434c67992d14da837f65ac0 | 2022-08-23 14:59:59.531352  
   6 | ea33278a5f8d75c75ddbcbf7d753367f | 2022-08-23 14:59:59.531355  
   7 | c98c67d0a08c2f6dc865a291997748d5 | 2022-08-23 14:59:59.531347  
   8 | 644215ca6c3f2ad0fc1c0387a8e5c4fb | 2022-08-23 14:59:59.53133  
   9 | d0b554588b4a1d3de9fddcac630234ea | 2022-08-23 14:59:59.531354  
  10 | 903c0dda9ddfbd241043b8d75b4eaf22 | 2022-08-23 14:59:59.531351  
(11 rows)  
  
Time: 2230.696 ms (00:02.231)

查看数据结构

postgres=# \d tbl_log  
                         Table "public.tbl_log"  
  Column  |            Type             | Collation | Nullable | Default   
----------+-----------------------------+-----------+----------+---------  
 gid      | integer                     |           |          |   
 info     | text                        |           |          |   
 crt_time | timestamp without time zone |           |          |

查看SQL执行计划:

返回11行记录(rows=11), 但是扫描了将近20万个数据块(shared hit=16167 read=30562, temp read=72167 written=72315, 耗时707.021毫秒), 并且使用了外部排序(external merge Disk: 288672kB, 耗时4382.093-707.021毫秒).

explain (analyze,verbose,timing,costs,buffers) select gid,info,crt_Time from   
  (select *, row_number() over (partition by gid order by crt_time desc) as rn from tbl_log) t  
where rn=1;   
  
                                                                 QUERY PLAN                                                                    
---------------------------------------------------------------------------------------------------------------------------------------------  
 Subquery Scan on t  (cost=1342550.98..1505051.08 rows=25000 width=45) (actual time=4382.105..5406.218 rows=11 loops=1)  
   Output: t.gid, t.info, t.crt_time  
   Filter: (t.rn = 1)  
   Buffers: shared hit=16167 read=30562, temp read=72167 written=72315  
   ->  WindowAgg  (cost=1342550.98..1442551.04 rows=5000003 width=53) (actual time=4382.103..5406.203 rows=11 loops=1)  
         Output: tbl_log.gid, tbl_log.info, tbl_log.crt_time, row_number() OVER (?)  
         Run Condition: (row_number() OVER (?) <= 1)  
         Buffers: shared hit=16167 read=30562, temp read=72167 written=72315  
         ->  Sort  (cost=1342550.98..1355050.99 rows=5000003 width=45) (actual time=4382.093..4997.855 rows=5000000 loops=1)  
               Output: tbl_log.gid, tbl_log.crt_time, tbl_log.info  
               Sort Key: tbl_log.gid, tbl_log.crt_time DESC  
               Sort Method: external merge  Disk: 288672kB  
               Buffers: shared hit=16167 read=30562, temp read=72167 written=72315  
               ->  Seq Scan on public.tbl_log  (cost=0.00..96729.03 rows=5000003 width=45) (actual time=0.026..707.021 rows=5000000 loops=1)  
                     Output: tbl_log.gid, tbl_log.crt_time, tbl_log.info  
                     Buffers: shared hit=16167 read=30562  
 Planning Time: 0.092 ms  
 Execution Time: 5507.738 ms  
(18 rows)  
  
Time: 5508.182 ms (00:05.508)

优化1:

建gid, crt_time desc索引.

postgres=# create index idx_tbl_log_1 on tbl_log (gid,crt_time desc);  
CREATE INDEX  
Time: 3530.425 ms (00:03.530)

重新查询后, 使用了索引, 但是性能并没有提升多少. 避免了外部排序, 但是依旧有大量的扫描(shared hit=16266 read=517194 written=8941, 耗时2736.351毫秒).

explain (analyze,verbose,timing,costs,buffers) select gid,info,crt_Time from   
  (select *, row_number() over (partition by gid order by crt_time desc) as rn from tbl_log) t  
where rn=1;   
  
                                                                          QUERY PLAN                                                                             
---------------------------------------------------------------------------------------------------------------------------------------------------------------  
 Subquery Scan on t  (cost=0.43..488005.99 rows=25000 width=45) (actual time=0.036..3116.007 rows=11 loops=1)  
   Output: t.gid, t.info, t.crt_time  
   Filter: (t.rn = 1)  
   Buffers: shared hit=16266 read=517194 written=8941  
   ->  WindowAgg  (cost=0.43..425505.99 rows=5000000 width=53) (actual time=0.035..3115.996 rows=11 loops=1)  
         Output: tbl_log.gid, tbl_log.info, tbl_log.crt_time, row_number() OVER (?)  
         Run Condition: (row_number() OVER (?) <= 1)  
         Buffers: shared hit=16266 read=517194 written=8941  
         ->  Index Scan using idx_tbl_log_1 on public.tbl_log  (cost=0.43..338005.99 rows=5000000 width=45) (actual time=0.026..2736.351 rows=5000000 loops=1)  
               Output: tbl_log.gid, tbl_log.crt_time, tbl_log.info  
               Buffers: shared hit=16266 read=517194 written=8941  
 Planning:  
   Buffers: shared hit=18 read=1 dirtied=2  
 Planning Time: 0.630 ms  
 Execution Time: 3116.041 ms  
(15 rows)

优化2:

为了解决扫描的问题, 引入递归查询, 需要修改SQL.

《重新发现PostgreSQL之美 - 6 index链表跳跳糖 (CTE recursive 递归的详细用例)》

with RECURSIVE tmp as (  
(select tbl_log as t from tbl_log order by gid, crt_time desc limit 1)  
union all   
select (select tbl_log from tbl_log where tbl_log.gid > (tmp.t).gid order by tbl_log.gid, tbl_log.crt_time desc limit 1) as t  
from tmp where tmp.* is not null   
)  
select (tmp.t).* from tmp   
where tmp.* is not null;  
  
  
 gid |               info               |          crt_time            
-----+----------------------------------+----------------------------  
   0 | 144ccff07b812d0ca5252ae8cbc2ad50 | 2022-08-23 14:59:59.531316  
   1 | 22fb4e6bb2daa15fcb8b00358bb4f3ad | 2022-08-23 14:59:59.531342  
   2 | 43761591e939309f1bb9e2b94f642e6d | 2022-08-23 14:59:59.531356  
   3 | 1751a3a7884685ec2c16926b4e2ad607 | 2022-08-23 14:59:59.531341  
   4 | 5df93803d19bf3a6bd19b7d017757bed | 2022-08-23 14:59:59.531348  
   5 | c11384fa2434c67992d14da837f65ac0 | 2022-08-23 14:59:59.531352  
   6 | ea33278a5f8d75c75ddbcbf7d753367f | 2022-08-23 14:59:59.531355  
   7 | c98c67d0a08c2f6dc865a291997748d5 | 2022-08-23 14:59:59.531347  
   8 | 644215ca6c3f2ad0fc1c0387a8e5c4fb | 2022-08-23 14:59:59.53133  
   9 | d0b554588b4a1d3de9fddcac630234ea | 2022-08-23 14:59:59.531354  
  10 | 903c0dda9ddfbd241043b8d75b4eaf22 | 2022-08-23 14:59:59.531351  
(11 rows)  
  
Time: 0.603 ms

扫描降低到了47个block, 同时避免了排序. 整体SQL耗时从5508.182毫秒降低到了0.6毫秒.

                                                                                  QUERY PLAN                                                                                    
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------  
 CTE Scan on tmp  (cost=61.21..63.23 rows=100 width=44) (actual time=0.061..0.342 rows=11 loops=1)  
   Output: (tmp.t).gid, (tmp.t).info, (tmp.t).crt_time  
   Filter: (tmp.* IS NOT NULL)  
   Rows Removed by Filter: 1  
   Buffers: shared hit=47  
   CTE tmp  
     ->  Recursive Union  (cost=0.43..61.21 rows=101 width=69) (actual time=0.047..0.316 rows=12 loops=1)  
           Buffers: shared hit=47  
           ->  Subquery Scan on "*SELECT* 1"  (cost=0.43..0.50 rows=1 width=69) (actual time=0.047..0.048 rows=1 loops=1)  
                 Output: "*SELECT* 1".t  
                 Buffers: shared hit=4  
                 ->  Limit  (cost=0.43..0.50 rows=1 width=81) (actual time=0.046..0.047 rows=1 loops=1)  
                       Output: tbl_log_1.*, tbl_log_1.gid, tbl_log_1.crt_time  
                       Buffers: shared hit=4  
                       ->  Index Scan using idx_tbl_log_1 on public.tbl_log tbl_log_1  (cost=0.43..338005.99 rows=5000000 width=81) (actual time=0.045..0.046 rows=1 loops=1)  
                             Output: tbl_log_1.*, tbl_log_1.gid, tbl_log_1.crt_time  
                             Buffers: shared hit=4  
           ->  WorkTable Scan on tmp tmp_1  (cost=0.00..5.97 rows=10 width=32) (actual time=0.019..0.019 rows=1 loops=12)  
                 Output: (SubPlan 1)  
                 Filter: (tmp_1.* IS NOT NULL)  
                 Rows Removed by Filter: 0  
                 Buffers: shared hit=43  
                 SubPlan 1  
                   ->  Limit  (cost=0.43..0.58 rows=1 width=81) (actual time=0.019..0.019 rows=1 loops=11)  
                         Output: tbl_log.*, tbl_log.gid, tbl_log.crt_time  
                         Buffers: shared hit=43  
                         ->  Index Scan using idx_tbl_log_1 on public.tbl_log  (cost=0.43..240899.23 rows=1666667 width=81) (actual time=0.018..0.018 rows=1 loops=11)  
                               Output: tbl_log.*, tbl_log.gid, tbl_log.crt_time  
                               Index Cond: (tbl_log.gid > (tmp_1.t).gid)  
                               Buffers: shared hit=43  
 Planning:  
   Buffers: shared hit=48  
 Planning Time: 0.538 ms  
 Execution Time: 0.391 ms  
(34 rows)

练习:
更多例子等你反馈, 欢迎联系我.

甚至你要了解数据分布, 扫描方法; 掌握数据库的基本原理(存储结构、索引结构、扫描优化器算法等)对优化是非常有帮助的, 可以帮助你从根源找问题并提出优化思路.

下面有个例子:

《PostgreSQL join+order by limit的优化例子 - 说明数据分布与扫描方法对优化的关键作用》

背景知识:

1 代码分析

https://www.man7.org/linux/man-pages/man1/perf.1.html

2 计划分析

https://www.postgresql.org/docs/devel/sql-explain.html

《PostgreSQL explain analyze 火山图火焰图图形化性能分析软件 pg_flame》

《PostgreSQL explain, parser, execute 过程资源使用统计分析 - perf , debug , log_planner_stats , log_xxx_stats》

《跨云的K8S cloud native postgresql管理系统谁在|会用? PG SaaS或工具或插件类产品谁在|会用? (SQL规整、执行计划解读和优化建议、参数优化、AWR、索引推荐、错误日志解读和应对策略)》

《PostgreSQL 查询当前执行中sql的执行计划 - pg_show_plans》

3 常用SQL

《PostgreSQL DBA最常用SQL》

《PostgreSQL dba常用扩展函数库 - pg_cheat_funcs》

《PostgreSQL DBA 日常管理 SQL》

《PostgreSQL 实时健康监控大屏 - 低频指标 - 珍藏级》

《PostgreSQL 实时健康监控大屏 - 高频指标(服务器) - 珍藏级》

《PostgreSQL 实时健康监控大屏 - 高频指标 - 珍藏级》

4 锁等待分析

《PostgreSQL 14 preview - 支持 lwlock blocking 诊断 - 增加 pg_lwlock_blocking_pid》

《PostgreSQL 谁堵塞了谁（锁等待检测）- pg_blocking_pids, pg_safe_snapshot_blocking_pids》

《PostgreSQL 谁堵塞了谁（锁等待检测）- pg_blocking_pids》

《PostgreSQL 锁等待监控珍藏级SQL - 谁堵塞了谁》

《PostgreSQL 锁等待排查实践 - 珍藏级 - process xxx1 acquired RowExclusiveLock on relation xxx2 of database xxx3 after xxx4 ms at xxx》

《PostgreSQL 锁等待跟踪》

5 索引推荐

《DB吐槽大会,第35期 - "富人"的烦恼?PG 不会自动选择索引类型》

《PostgreSQL 自动化后台并行创建多索引, 加速导入速度 - pg_parallizator》

《PostgreSQL 自动化索引 - auto-indexing-PostgreSQL》

《PostgreSQL SQL自动优化案例 - 极简，自动推荐索引》

《自动选择正确索引访问接口(btree,hash,gin,gist,sp-gist,brin,bitmap...)的方法》

《powa4 PostreSQL Workload Analyzer - PostgreSQL监控工具、带WEB展示 - 索引推荐,等待事件分析,命中率,配置变更跟踪等》

《PostgreSQL 商用版本EPAS(阿里云ppas(Oracle 兼容版)) 索引推荐功能使用》

《PostgreSQL 9种索引的原理和应用场景》

《PostgreSQL 复杂SQL执行计划优化修正插件: pg_plan_inspector , pg_plan_advsr , pg_hint_plan , pg_store_plans》

6 memory context 分析

《PostgreSQL 15 preview - pg_log_backend_memory_contexts 增强, 可打印辅助进程(vacuum, checkpointer等)的内存信息》

《PostgreSQL 14 preview - 打印其他会话的memory context, 诊断内存消耗问题 - pg_log_backend_memory_contexts(pid)》

《PostgreSQL 14 preview - 查看backend process的memory context》

《PostgreSQL cheat functions - (内存上下文\planner内容\memory context等常用函数)》

7 固定、篡改、保存执行计划. (对于SQL不能修改的场景, 解决SQL因执行计划不正确产生的问题.)

《PostgreSQL hint pg_hint_plan 的详细用法》

《PostgreSQL Oracle 兼容性之 - SQL OUTLINE插件sr_plan (保存、篡改、固定执行计划)》

8 动态执行计划

《[未完待续] PostgreSQL PRO 特性 - AQO(机器学习执行计划优化器)》

9 膨胀检查与清理

《PostgreSQL pgstattuple - 检查表的膨胀情况、dead tuples、live tuples、freespace》

《解读用户最常问的PostgreSQL垃圾回收、膨胀、多版本管理、存储引擎等疑惑 - 经典》

《PostgreSQL 收缩膨胀表或索引 - pg_squeeze or pg_repack》

《PostgreSQL 垃圾回收原理以及如何预防膨胀 - How to prevent object bloat in PostgreSQL》

《PostgreSQL 如何精确计算表膨胀(fsm,数据块layout讲解) - PostgreSQL table exactly bloat monitor use freespace map data》

《如何使用5why分析法发现数据库膨胀现象背后的本质?》

《膨胀点解释 - 全局catalog,库级catalog,普通表,wal文件 - 哪些垃圾(dead tuple), wal文件不能被回收reuse - 什么情况下可能膨胀》

10 自动收集统计信息配置

autovacuum

二、整体慢

数据库整体变慢, 最核心的是定位罪魁祸首, 进行优化, 最后需要判断是否在业务层面、数据库SQL层面、数据库内核层面都已经无法优化(则可能需要升级硬件、或者使用分布式数据库、扩容等),

常用分析工具与方法:

pg_stat_statements, 找出最消耗资源的TOP SQL
performance insight, 活跃会话、等待事件采样快照记录, 用于分析活跃会话数超过CPU 核数的时间段, 当时数据库系统的等待情况. SQL的分布等.
perf, 借助抓取系统调用、用户进程函数调用等统计信息, 生成数据库高峰、或者问题时刻的代码级耗时统计的火焰图, 找到代码级别的瓶颈. 通常用于分析表面上很难察觉的问题.
pg_stat_ pg_statio_ 统计信息, 找出CPU消耗、IO消耗不合理的表
找出膨胀索引与膨胀表, 垃圾清理不及时的原因分析
找出统计信息偏差, 配置自动收集统计信息
参数不正确、优化器校准因子不正确等问题
- 《DB吐槽大会,第12期 - 没有自动成本校准器》

例子:

《PostgreSQL性能优化综合案例讲解 - 1》

《PostgreSQL性能优化综合案例讲解 - 2》

练习:
更多例子等你反馈, 欢迎联系我.

背景知识:

1 找出最消耗资源的SQL

《PostgreSQL 如何查找TOP SQL (例如IO消耗最高的SQL) (包含SQL优化内容) - 珍藏级 - 数据库慢、卡死、连接爆增、慢查询多、OOM、crash、in recovery、崩溃等怎么办?怎么优化?怎么诊断?》

2 找出问题时间段, 找出问题时间段的等待事件瓶颈, 分析等待事件的SQL分布, 分析慢SQL的等待事件分布

《PostgreSQL Oracle 兼容性之 - performance insight - AWS performance insight 理念与实现解读 - 珍藏级》

《PostgreSQL pg_stat_statements AWR 插件 pg_stat_monitor , 过去任何时间段性能分析 [推荐、收藏]》

https://github.com/postgrespro/pg_wait_sampling

《PostgreSQL 13 preview - wait event sample - 等待事件统计(插件,hook) - ASH - performance insight》

《PostgreSQL 等待事件及等待采样统计 (pg_wait_sampling) 发布新版本 1.1.2》

《PostgreSQL 等待事件及等待采样统计(pg_wait_sampling)》

3 找出代码瓶颈

《PostgreSQL 源码性能诊断(perf profiling)指南(含火焰图生成分析FlameGraph) - 珍藏级》

《PostgreSQL explain, parser, execute 过程资源使用统计分析 - perf , debug , log_planner_stats , log_xxx_stats》

4 找出CPU消耗、IO消耗不合理的表

《PostgreSQL pg_stat_ pg_statio_ 统计信息(scan,read,fetch,hit)源码解读》

5 找出膨胀索引与膨胀表

《PostgreSQL pgstattuple - 检查表的膨胀情况、dead tuples、live tuples、freespace》

《解读用户最常问的PostgreSQL垃圾回收、膨胀、多版本管理、存储引擎等疑惑 - 经典》

《PostgreSQL 收缩膨胀表或索引 - pg_squeeze or pg_repack》

《PostgreSQL 垃圾回收原理以及如何预防膨胀 - How to prevent object bloat in PostgreSQL》

《PostgreSQL 如何精确计算表膨胀(fsm,数据块layout讲解) - PostgreSQL table exactly bloat monitor use freespace map data》

《如何使用5why分析法发现数据库膨胀现象背后的本质?》

《膨胀点解释 - 全局catalog,库级catalog,普通表,wal文件 - 哪些垃圾(dead tuple), wal文件不能被回收reuse - 什么情况下可能膨胀》

三、偶尔慢

偶尔某些很快的SQL会抖动(变得很慢). 针对这个情况, 需要找到这条SQL变慢的时刻, 当时数据库的整体资源消耗的情况, 以及当时这条SQL的执行计划、锁等待的情况.

比较典型的例如prepare, 输入参数不同可能会有不一样的资源消耗, 或者执行计划不正确导致.
又或者遇到较长的锁等待. (包括低级锁lwlock、或者高级锁lock)

常用分析工具与方法:

auto_explain, 记录执行时间超过阈值的SQL、函数的执行计划, 执行过程的完整数据(buffer, hit, read, write, rows, time等)
log_lock_waits, 记录锁等待时间超过lock_timeout的SQL, 以及堵塞它的PID.
performance insight, 活跃会话、等待事件采样快照记录, 用于分析SQL抖动的对应时间段的数据库实例整体情况、SQL当时的等待情况.

例子, 使用pg_stat_activity活跃会话快照, 分析过去抖动时刻的慢SQL等待事件:

《PostgreSQL Oracle 兼容性之 - performance insight - AWS performance insight 理念与实现解读 - 珍藏级》

练习:
更多例子等你反馈, 欢迎联系我.

背景知识:

1 分析过去某个时刻的执行计划抖动.

《PostgreSQL 函数调试、诊断、优化 & auto_explain & plprofiler》

2 找出问题时间段, 找出问题时间段的等待事件瓶颈, 分析等待事件的SQL分布, 分析慢SQL的等待事件分布

《PostgreSQL Oracle 兼容性之 - performance insight - AWS performance insight 理念与实现解读 - 珍藏级》

《PostgreSQL pg_stat_statements AWR 插件 pg_stat_monitor , 过去任何时间段性能分析 [推荐、收藏]》

https://github.com/postgrespro/pg_wait_sampling

《PostgreSQL 13 preview - wait event sample - 等待事件统计(插件,hook) - ASH - performance insight》

《PostgreSQL 等待事件及等待采样统计 (pg_wait_sampling) 发布新版本 1.1.2》