已执行3s或5s SQL数问题定位及处理方法

指标异常说明（影响）

表示当前业务中SQL运行较慢，SQL无法及时获取结果。

问题排查思路

数据库SQL执行慢的原因大概有以下几种：

• SQL被阻塞，在等待其他事务执行完成。
• 当前系统中CPU等系统资源使用率高，导致SQL运行时间长。
• 缺少索引导致SQL执行慢。
• SQL中使用排序导致IO执行时间长。

排查方法

• SQL阻塞排查方法
  1. 找到等锁进程。

     SELECT locktype, relation, relation::regclass AS relname, virtualxid, transactionid, virtualtransaction, pid, mode, granted FROM pg_locks where granted = 'f';

  2. 从1中获取到等锁进程pid，查找阻塞该进程的进程（查询结果的pg_blocking_pids字段）。

     select pg_blocking_pids(pid), array_length(pg_blocking_pids(pid), 1) blocking_num, * from pg_stat_activity  where pid = <pid from step 1> order by blocking_num;

  3. 查找阻塞的SQL。

     select * from pg_stat_activity where pid = <pid from step 2>;

  4. 确认被阻塞的SQL，假设为update xxx;，通过pg_stat_activity查看阻塞该进程pid。
     • pg_blocking_pids：阻塞进程ID
     • wait_event_type：等待事件的类型

     select pg_blocking_pids(pid), array_length(pg_blocking_pids(pid), 1) blocking_num, *
     from pg_stat_activity 
     where query like '%update xxx%' 
     and pid <> pg_backend_pid()
     order by blocking_num desc NULLS LAST;

     当找到阻塞SQL的pid后，可以通过SELECT pg_terminate_backend($PID);结束该进程。

• 系统资源使用率高，导致SQL运行时间长的排查方法

  在正常业务情况下，执行SQL返回结果很慢，根据SQL阻塞排查方法没有发现阻塞，此时可以通过监控指标来协助判断。

  通过管理控制台中的CPU使用率监控项，查看近7天是否长期处于高位状态，如下图所示。

  图1 查看CPU使用率
  

  如果看到CPU使用率长期稳定在80%以上，再查看硬盘读吞吐量和硬盘写吞吐量监控项，查看业务是否一直有读写，如下图所示。

  图2 查看硬盘吞吐量
  

  此外，找到执行慢的SQL，在业务低峰期执行看是否同样很慢，如果低峰期执行很快，此时根据以上信息可以判断，是由于系统资源使用率高导致SQL运行时间长。

• 缺少索引导致SQL执行慢

  找到执行慢的SQL，查看执行计划explain (ANALYZE, VERBOSE, BUFFERS)，通过执行计划确认：

  xxx1:15:33.140 +08:10.51.11.21(53162):xxx:LOG:  duration: 22035.462 ms  plan:
      Query Text:  xxxxxxxxxxxxxx
      Nested Loop  (cost=1.07..892.50 rows=1 width=806)
        Join Filter: ((xxx))
        ->  Nested Loop  (cost=1.07..25.41 rows=1 width=565)
              ->  Nested Loop  (cost=0.66..16.97 rows=1 width=523)
                    ->  Index Scan using xxx  (cost=0.25..8.54 rows=1 width=318)
                          Filter: ((itype = 1) AND (dr = 0))
                    ->  Index Scan using xxxx  (cost=0.41..8.43 rows=1 width=247)
                          Index Cond: (xxx)
              ->  Index Scan using xxx  (cost=0.41..8.43 rows=1 width=84)
                    Index Cond: (xxx)
        ->  Seq Scan on xxx log2  (cost=0.00..867.00 rows=1 width=66)

  在执行计划中看到有个表走了全表扫描并且花费的时间最多。

  Seq Scan on xxx log2

  此时需要业务确认：

  1. 在该表上是否有索引。
  2. 该表在执行业务过程中是否有大量的数据做增删改查操作。

  如果业务确认后，此时需要重建索引后再次执行SQL查看是否还存在慢SQL的问题。

• SQL中使用排序导致IO执行时间长

  如果执行的SQL中有GROUP BY操作，类似于如下SQL语句：

  select xx1,xx2,xx3,xx4,xx5,xx6
          from tbl_xxx
          GROUP BY xx1,xx2,xx3,xx4,xx5,xx6;

  此时SQL执行时间长，可以通过执行计划explain (ANALYZE, VERBOSE, BUFFERS)，查看SQL具体执行时间：

  xxxx  (cost=439756.01..470149.19 rows=189957 width=28) (actual time=18072.697..20311.874 rows=323770 loops=1)
    Group Key: xxxx, xxxx
    Filter: (xxxxxx)
    Rows Removed by Filter: 192
    ->  Sort  (cost=439756.01..444504.94 rows=1899574 width=20) (actual time=18072.671..19960.595 rows=1834158 loops=1)
          Sort Key: xxxxxxxxxx
          Sort Method: external merge  Disk: 61056kB
          ->  Result  (cost=0.00..163739.61 rows=1899574 width=20) (actual time=0.009..927.709 rows=1834158 loops=1)
                ->  Append  (cost=0.00..144743.87 rows=1899574 width=20) (actual time=0.008..791.301 rows=1834158 loops=1)
                      ->  Seq Scan on xxxx  (cost=0.00..0.00 rows=1 width=212) (actual time=0.004..0.004 rows=0 loops=1)

  在执行计划中，可以看到“Sort Method: external merge Disk: 61056kB”表示排序操作占用了磁盘的IO，此时可以通过如下SQL关闭顺序查询，再次查看执行计划。

  set enable_seqscan = off;

  如果执行计划中排序操作仍然使用的磁盘的IO，那么此时可以通过调整“work_mem”参数来增大查询的内存。

  

  “work_mem”参数请结合实际业务需要进行配置，如果配置的参数值过大，可能会导致内存OOM。

解决方法

• SQL阻塞

  当定位到阻塞的SQL后，可以通过SELECT pg_terminate_backend($PID);结束该进程。

  结束后再执行1，进一步确认是否还存在其他锁冲突的情况。

• 系统资源使用率高，导致SQL运行时间长

  优化业务，减少业务并发。

• 缺少索引导致SQL执行慢

  重新创建索引，走索引查询。

• SQL中使用排序导致IO执行时间长

  增大“work_mem”参数值，减少排序的IO执行时间。