一个慢查询引发的血案

作者: 长江十三寨总瓢把子 | 来源:发表于2017-11-05 21:40 被阅读0次

1. 前戏

正当下班之际，zabbix突然告警，生产一台主机上的PG出现了一个5分多钟的长事务，持续了近15分钟还没结束。卧槽？！赶紧上去看看，发现与此同时，PG中出现了100多个慢查询。打开日志，扒出慢查询SQL，扔到生产环境，explain了一把，执行计划如下，问题很明显，红框内的表（后面称为A表）没有索引。

slowquery_plan_1011.png
于是乎，解决办法也很简单，因为业务是多维度的查询，条件组合多，我们建议为A表建一个gin索引。建完索引，该SQL执行时间降为毫秒级，问题解决~

但是。。。。

2. 开端

第二天早上上班，打开电脑，发现该库又有告警，这次更夸张，一个事务已经运行了近10个小时，还没结束。赶紧登录到数据库看看是咋回事，通过系统表pg_stat_activity，查看当前正在运行的SQL

select pid,query from pg_stat_activity where pid  <> pg_backend_pid() and state = 'active' and xact_start < now() - '600 s'::interval;

但是query字段只能记录1000字节的内容，而SQL本身又很长，取不到完整SQL。同时，没有执行完的SQL是不会记录到日志的，咋办？
必须要把完整SQL抓出来，杀手锏吧，GDB attach到长事务进程，把内存里的SQL变量给dump出来！

3. 高潮

正当我们忙于抓SQL，分析原因的时候，CPU利用率这货一直在默默地往上爬。。。超过90%且持续15分钟之后，告警了。同时，由于CPU满负荷，直接导致业务无法访问，业务部门开始急了，怎么没法访问报表了？！
那么，恢复业务是当务之急。我们决定杀掉目前的所有慢SQL，尽快降低CPU负载

select pg_terminate_backend(pid);

然而，这个函数并不能将所有SQL全部杀掉，有些进程杀不掉（原因不明），负载仍是居高不下。事态紧急之下，我们急急忙忙之中考虑欠佳，做了个错误的决定：用OS的kill命令杀进程

kill -9 pid

按下回车之后，PG直接强制重启！（应该是PG的保护机制，当内存中还有数据未落盘，要确保数据一致性，强制重启了）
完，后悔晚矣~算了，PG宕机恢复，追WAL的速度还是挺快的（生产机器是物理机SSD的硬盘），我们觉得应该很快能恢复。
但是我们不断的ps，始终没发现PG的redo进程，似乎startup进程一直处于等待状态。嗯？这不科学啊，有问题。
一拍脑袋，卧槽！刚才dump慢查询的GDB进程还没有退出，所以startup在等他！赶紧跑过去quit，然后PG真正开始重启恢复，用时7分钟。

2017-10-12 10:50:42.144 CST 30865     LOG:  redo starts at 1031/E34C5798
...
2017-10-12 10:57:00.945 CST 30865     LOG:  redo done at 1034/CCA0F328
2017-10-12 10:57:00.945 CST 30865     LOG:  last completed transaction was at log time 2017-10-12 10:40:14.587039+08
2017-10-12 10:57:01.309 CST 30865     LOG:  checkpoint starting: end-of-recovery immediate
...
2017-10-12 10:57:58.630 CST 30865     LOG:  checkpoint complete: wrote 4194029 buffers (100.0%); 0 transaction log file(s) added, 753 removed, 132 recycled; write=55.055 s, sync=0.180 s, total=57.321 s; sync files=334, longest=0.180 s, average=0.000 s; distance=12211494 kB, estimate=12211494 kB
2017-10-12 10:57:58.637 CST 30865     LOG:  MultiXact member wraparound protections are now enabled
2017-10-12 10:57:58.645 CST 2612     LOG:  autovacuum launcher started
2017-10-12 10:57:58.646 CST 12183     LOG:  database system is ready to accept connections

计算下WAL的redo速度，大约28MB/s，计算方式如下：

test=# select pg_xlog_location_diff('1034/CCA0F328','1031/E34C5798');
 pg_xlog_location_diff 
-----------------------
           12504570768
(1 row)
test=# select 12504570768.0/1024/1024/(7*60);
      ?column?       
---------------------
 28.3935428074428024
(1 row)

4. 中场休息

重启之后，负载恢复正常，松一口气，我们又回到最初的那个慢查询上去。慢查询SQL和前一天晚上的慢查询SQL基本一致，老办法，我们explain一把。

slowquery_plan_1012.png
我们发现执行计划走了嵌套循环，而且列tmall_flg因为带了类型强转而没走索引。那么我们认为，由于类型强转，导致查询优化器对rows的估算错误，认为行数不多而选择了嵌套循环。类型强转对行数估算的影响，请参考前辈的分析：
http://blog.chinaunix.net/uid-20726500-id-5772847.html
那么理所当然的，我们希望可以去掉类型强转，然而。。这是应用自动生成的SQL，是固定的模板，不好改。唉，无奈。。。我们只能再想别的办法，从数据库层面回避这个问题。

5. 一波三折

就在我们对PG的查询优化器做调查分析的几天当中，生产库还是时不时的会爆发慢查询，而且都是同一条SQL。正常情况下，这条SQL执行时间大概是500ms左右，而爆发时可以长达70s，甚至100s。
对比执行计划，正常情况，是哈希JOIN

Subquery Scan on "SQL1"  (cost=870264.92..871760.18 rows=11076 width=360) (actual time=622.934..623.570 rows=60 loops=1)
   ->  GroupAggregate  (cost=870264.92..871178.69 rows=11076 width=273) (actual time=622.909..623.415 rows=60 loops=1)
         Group Key: a.site_cd, c.site_nm, a.z_werks, d.vtext, a.vbeln_old_date
         ->  Sort  (cost=870264.92..870292.61 rows=11076 width=172) (actual time=622.879..622.912 rows=332 loops=1)
               Sort Key: a.site_cd, c.site_nm, a.z_werks, d.vtext, a.vbeln_old_date
               Sort Method: quicksort  Memory: 113kB
               ->  Hash Left Join  (cost=1032.81..869520.88 rows=11076 width=172) (actual time=469.451..621.905 rows=332 loops=1)
                     Hash Cond: ((a.z_werks)::text = (d.zexid)::text)
                     ->  Hash Join  (cost=257.13..868626.09 rows=11076 width=142) (actual time=464.641..616.938 rows=332 loops=1)
                           Hash Cond: ((c.area_cd)::text = (m.area_cd)::text)
                           ->  Hash Join  (cost=254.16..866473.52 rows=44083 width=147) (actual time=319.290..615.064 rows=17929 loops=1)
                                 Hash Cond: ((a.site_cd)::text = (c.site_cd)::text)
                                 ->  Index Scan using idx1_zl057_rt on tdm_wh_zl057_rt a  (cost=0.56..865613.69 rows=44108 width=115) (actual time=316.988..601.362 rows=17934 loo
ps=1)
                                       Index Cond: (((vbeln_old_date)::text >= '20171012'::text) AND ((vbeln_old_date)::text <= '20171012'::text) AND ((zsize)::text = '2'::text))
                                 ->  Hash  (cost=191.60..191.60 rows=4960 width=37) (actual time=2.244..2.244 rows=4962 loops=1)
                                       Buckets: 8192  Batches: 1  Memory Usage: 399kB
                                       ->  Seq Scan on tsor_site_area_rl_td c  (cost=0.00..191.60 rows=4960 width=37) (actual time=0.011..1.031 rows=4962 loops=1)
                           ->  Hash  (cost=2.53..2.53 rows=35 width=5) (actual time=0.023..0.023 rows=1 loops=1)
                                 Buckets: 1024  Batches: 1  Memory Usage: 9kB
                                 ->  Index Only Scan using idx1_emp_area on tsor_emp_area_d m  (cost=0.42..2.53 rows=35 width=5) (actual time=0.018..0.018 rows=1 loops=1)
                                       Index Cond: (emp_no = '15071175'::text)
                                       Heap Fetches: 0
                     ->  Hash  (cost=651.97..651.97 rows=9897 width=40) (actual time=4.731..4.731 rows=9897 loops=1)
                           Buckets: 16384  Batches: 1  Memory Usage: 841kB
                           ->  Seq Scan on tssa_les_ztmt038_d d  (cost=0.00..651.97 rows=9897 width=40) (actual time=0.006..2.309 rows=9897 loops=1)
 Planning time: 1.639 ms
 Execution time: 623.891 ms
(27 rows)

而慢查询出现时，是NEST LOOP

Subquery Scan on "SQL1"  (cost=828728.81..828728.94 rows=1 width=360) (actual time=65616.743..65617.363 rows=60 loops=1)
   ->  GroupAggregate  (cost=828728.81..828728.89 rows=1 width=273) (actual time=65616.725..65617.215 rows=60 loops=1)
         Group Key: a.site_cd, c.site_nm, a.z_werks, d.vtext, a.vbeln_old_date
         ->  Sort  (cost=828728.81..828728.81 rows=1 width=172) (actual time=65616.691..65616.728 rows=328 loops=1)
               Sort Key: a.site_cd, c.site_nm, a.z_werks, d.vtext, a.vbeln_old_date
               Sort Method: quicksort  Memory: 112kB
               ->  Nested Loop  (cost=0.98..828728.80 rows=1 width=172) (actual time=633.708..65615.630 rows=328 loops=1)
                     ->  Nested Loop Left Join  (cost=0.56..828727.45 rows=1 width=177) (actual time=319.379..65548.504 rows=17902 loops=1)
                           Join Filter: ((a.z_werks)::text = (d.zexid)::text)
                           Rows Removed by Join Filter: 177158902
                           ->  Nested Loop  (cost=0.56..827951.77 rows=1 width=147) (actual time=316.841..22950.620 rows=17902 loops=1)
                                 Join Filter: ((a.site_cd)::text = (c.site_cd)::text)
                                 Rows Removed by Join Filter: 88836632
                                 ->  Index Scan using idx1_zl057_rt on tdm_wh_zl057_rt a  (cost=0.56..827698.17 rows=1 width=115) (actual time=315.916..665.026 rows=17907 loops=1
)
                                       Index Cond: (((vbeln_old_date)::text >= '20171012'::text) AND ((vbeln_old_date)::text <= '20171012'::text) AND ((zsize)::text = '2'::text))
                                 ->  Seq Scan on tsor_site_area_rl_td c  (cost=0.00..191.60 rows=4960 width=37) (actual time=0.001..0.432 rows=4962 loops=17907)
                           ->  Seq Scan on tssa_les_ztmt038_d d  (cost=0.00..651.97 rows=9897 width=40) (actual time=0.001..0.941 rows=9897 loops=17902)
                     ->  Index Only Scan using idx1_emp_area on tsor_emp_area_d m  (cost=0.42..1.33 rows=1 width=5) (actual time=0.003..0.003 rows=0 loops=17902)
                           Index Cond: ((emp_no = '15071175'::text) AND (area_cd = (c.area_cd)::text))
                           Heap Fetches: 0
 Planning time: 1.627 ms
 Execution time: 65617.566 ms

执行计划不稳定，我们注意到每次出现NEST LOOP时，查询优化器都认为A表只有1行数据，只需要循环1次，而实际上却有近1万7千多行。那么问题的根源应该是统计信息不准确，误导了查询优化器。
我们从业务处得知，A表每5分钟就会删除7天旧数据，再插入7天新数据，那么有可能是数据删除之后PG做了analyze，此时行数为0，但是很快数据又插入了，却没来得及analyze，统计信息没更新，select就来了，那么肯定就出问题了。
那么解决方案，有这么几个考虑：

通过set enable_nestloop = off禁掉嵌套循环
停掉A表的autoanalyze，改为每次更新完之后手动analyze
因为A表数据量是恒定的，考虑每天只更新一次统计信息，降低出错几率

经过讨论，应用内不支持方案1这种sql，放弃；因为更新频繁，所以担心方案2会增加系统负载，放弃。最终选择了方案3，我们每天零点十分，更新一次A表的统计信息，然后通过设置A表的autovacuum_analyze_threshold (integer)参数，禁掉A表的autoanalyze

alter table a set (autovacuum_analyze_threshold = 2000000000)

6. 未完待续

就这样相安无事了2天，第三天早上，又有慢查询出现，不过数量不多，我们认为可能是零点十分收集的统计信息包含错误的内容，于是乎手动执行了一次收集统计信息的脚本，慢查询消失了。
但是，到了周六下午，又一次大规模爆发慢查询，还是这玩意儿。我们只得从家赶到公司，救急！如果我们之前的分析是对的，那么不应该再有大规模的慢查询，如果统计信息有误，应该一整天都是慢查询，为何仍是时好时坏呢？
完事到了周一，我们只能全组坐下来，静静地分析，根源到底在哪？

7. 刨根问底

我们写了两个脚本，一个循环跑慢查询SQL，一个同步收集pg_stats视图里A表相关的内容，期望抓到出问题时刻的统计信息究竟是怎样的。
慢SQL的查询条件中最主要的过滤条件是这个，根据日期筛选

( a.VBELN_OLD_DATE>=('20171012')  AND a.VBELN_OLD_DATE<=('20171012')

然后我们分析上面收集到的统计信息，发现出问题的时候，条件中的日期值从most common values中转移到了histogram_bounds当中，那么问题来了，是不是基于柱状图的行估算有问题呢？
翻阅PG手册，有算法介绍：
http://www.postgres.cn/docs/9.6/row-estimation-examples.html

同时，我们发现，业务对A表的更新（先删除再插入）是被包裹在一个函数之中完成的，即是在一个事务中完成的，那么理论上来说，事务不提交，autoanalyze是不会被触发的（测试验证，确实如此）。基于这个结论，那么我们最初推断的统计信息不准备的结论肯定是不对的了。

8. 故事结局

经过分析，发现确实是基于柱状图的行估算算法导致的问题。
基于柱状图的行估算测试，如果where条件的值只在柱状图中出现1次，那么估算结果如下

如果where里面是范围查询（>= <=或者between and），PG在行估算时是无视等号的，换言之大于等于和大于，结果一样，那么如果范围的左边界和右边界相等，此时PG就认为该区间的间隔就是0，即没有数据，所以行数永远是1。

        test=# explain select * from bi_dm.tdm_wh_zl057_rt where ((vbeln_old_date)::text >= '20170428'::text) and ((vbeln_old_date)::text <= '20170428'::text);
                                                      QUERY PLAN                                                   
        ---------------------------------------------------------------------------------------------------------------
        Index Scan using idx1_zl057_rt on tdm_wh_zl057_rt  (cost=0.56..119710.58 rows=1 width=162)
        Index Cond: (((vbeln_old_date)::text >= '20170428'::text) AND ((vbeln_old_date)::text <= '20170428'::text))
        (2 rows)

        test=# explain select * from bi_dm.tdm_wh_zl057_rt where ((vbeln_old_date)::text > '20170428'::text) and ((vbeln_old_date)::text < '20170428'::text);
                                                 QUERY PLAN                                                  
        -------------------------------------------------------------------------------------------------------------
        Index Scan using idx1_zl057_rt on tdm_wh_zl057_rt  (cost=0.56..119710.58 rows=1 width=162)
        Index Cond: (((vbeln_old_date)::text > '20170428'::text) AND ((vbeln_old_date)::text < '20170428'::text))
        (2 rows)

如果where里面不用范围查询，把上面的条件换成等值查询，那么结果就是准确的

        test=# explain select * from bi_dm.tdm_wh_zl057_rt where ((vbeln_old_date)::text = '20170428'::text);
                                          QUERY PLAN                                           
        -----------------------------------------------------------------------------------------------
        Index Scan using idx1_zl057_rt on tdm_wh_zl057_rt  (cost=0.56..112348.11 rows=3217 width=162)
        Index Cond: ((vbeln_old_date)::text = '20170428'::text)
        (2 rows)

如果范围查询有一定的区间间隔，下例中隔了1天，那么评估的行数相对会更合理一些。

        test=# explain select count(*) from bi_dm.tdm_wh_zl057_rt where vbeln_old_date between '20170428'::text and '20170429'::text;
                                              QUERY PLAN                                              
        -------------------------------------------------------------------------------------------------------
        Aggregate  (cost=119630.26..119630.27 rows=1 width=8)
        ->  Index Only Scan using idx1_zl057_rt on tdm_wh_zl057_rt  (cost=0.56..119629.80 rows=186 width=0)
         Index Cond: ((vbeln_old_date >= '20170428'::text) AND (vbeln_old_date <= '20170429'::text))
        (3 rows)

如果where条件的值在柱状图中2次([20171017,20171017])，即存在一个单值的区间，而不是一个点的情况((20171017,20171017))，那么估算的方法我认为是这样的：

rows = reltuples * (1-sum(most_common_freqs))/100

其中reltuples来自pg_class，100是指柱状图的区间个数，默认是100，总行数乘以常见值之外值的比例，得到柱状图中值的行数总和，再均分给每个区间。这是我通过测试得出的结论，是否真是如此，需要去代码中确认下。

那么弄清楚问题根本原因，解决办法就有了，业务SQL格式固定，无法替换成等值查询，那么唯一的办法就是让区间范围不是0。

业务方更改SQL之后，到目前为止2周，再也没发生过慢查询的问题~

小结

事情解决了，回过头来想想其实问题原因很简单，但是过程却是异常曲折，这之中有很多值得吸取的教训

理论上，生产上是不允许GDB的，风险太大
每次出事，都有点手忙脚乱，甚至误操作导致数据库重启，这是非常不应该的，需要有可操作强，针对性强的应急预案
业务SQL在设计之初，应该尽可能回避会导致问题的写法，后期修改的成本太高了
PG的查询优化器对行估算还有优化的空间，PG10的自定义统计信息不知是否可以解决这类问题

一个慢查询引发的血案

1. 前戏

2. 开端

3. 高潮

4. 中场休息

5. 一波三折

6. 未完待续

7. 刨根问底

8. 故事结局

小结

相关文章

网友评论

延伸阅读

深度阅读

栏目导航

热点阅读