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

在优化之前

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

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

《PostgreSQL 数据库开发规范》

《PostgreSQL 持续稳定使用的小技巧 - 最佳实践、规约、规范》

《PostgreSQL 11 postgresql.conf 参数模板 - 珍藏级》

《PostgreSQL on Linux 最佳部署手册 - 珍藏级》

一、单一慢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)

建 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)

为了解决扫描的问题, 引入递归查询, 需要修改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)