PostgreSQL IO/CPU异常排查

1,223 阅读5分钟

持续创作,加速成长!这是我参与「掘金日新计划 · 6 月更文挑战」的第1天,点击查看活动详情

问题背景

问题发生在4月下旬的一段时间,当时我发现自己负责的任务处理平台,加载信息页面有点慢,期初以外是网络不好,我们的服务部署在美区的AWS的一台EC2 机器上,后来过了2天 发现还是很慢,问了下同事 他们也反馈有点儿慢,有时间加载一个列表要十几二十秒,哈哈 他们的容忍度好高呀,后来我就去研究下,发现前端请求的API接口Waiting的时间很长,看来是接口内部出现了问题

排查问题

既然接口加载的慢,那我就去看了下 是否数据库存在了问题,系统的数据库采用了AWS RDS-PostpreSql ,接下来 我就去Console 页面 看下 数据的的一些监控指标,发现CPU 和IO 都存在了一些异常

image.png

image.png

从图中 可以看出 数据库的CPU 使用 存在波峰的情况,IO 也是 最高的读取IOPS 达到了10000次每秒,这显然 存在问题

找到问题

Git Commit

根据CPU的使用情况,我怀疑 应该是我们系统中 存在一个定时任务 导致的,由于我负责的是一个任务处理平台,其中一个组成就有定时任务系统,此系统主要是做 服务的动态伸缩,任务的状态统计,以及服务状态的同步等等。

既然是这个问题,那我首先从最近的git commit 记录中查找是否有相关代码的改动 ,找了一会儿,我发现 并没有相关的Changes,于是我慌了,好好的 为啥这个样子,一下不知如何下手了,于是我打算从Postgresql 入手,看看数据库系统是否 提供一些统计信息等来提供给我分析参考。

PostgreSql

我在AWS 的官网中 找到了一遍 分析RDS CPU 高的文章:aws.amazon.com/cn/premiums…

其中提到了 使用 pg_stat_statements 来分析 问题,于是 我又找到了 PG 的官方文档来学习下pg_stat_statements的使用,我这边使用的PG-11 所以 问题如下:www.postgres.cn/docs/11/pgs…

里面还有详细的描述 我就不一一列举了

下面是 我感觉对我有用的3个SQL,如下:

-- 总耗时做多的SQL
SELECT userid::regrole, dbid,query, calls, total_time,max_time,mean_time,min_time,rows, 100.0 * shared_blks_hit /
nullif(shared_blks_hit + shared_blks_read, 0) AS hit_percent,blk_read_time,blk_write_time
FROM pg_stat_statements ORDER BY total_time DESC LIMIT 5;
​
​
-- 最耗IO SQL,单次调用最耗IO SQL
select userid::regrole, dbid, query,shared_blks_hit,shared_blks_read,blk_read_time,blk_write_time,calls,max_time,mean_time,rows   from pg_stat_statements order by (blk_read_time+blk_write_time)/calls desc limit 10;
​
​
-- 平均耗时高的SQL 
select  userid::regrole,dbid,calls,total_time /calls AS avg_time,total_time,max_time,mean_time,min_time,query 
FROM pg_stat_statements
ORDER BY avg_time DESC LIMIT 10;
​

后来我在 我使用的了 CREATE EXTENSION pg_stat_statements 命令 开启了启用

pg_stat_statements 分析

经过了大概一段时间的指标收集,我执行了 总耗时做多的SQL,结果如下:

image.png

当我看到第一个 我就发现 这个Calls 很高呀,而且总耗时也很高呀,算下来平均一个达到了2s, 这个仅仅是一个Select 单点查询,不至于这么慢呀,我猜测 这个地方 可能出现了问题,于是 是使用了\d 这张表,输出了 这张表的 表结构信息,如下

image.png

一看到这边 ,我发现有问题呀,这张表和ecs_task_id 有关的索引 是一个联合索引,我们从图中可以看出,但是尴尬的ecs_task_id是处于联合索引的第二个字段,也就是说 如果单独使用ecs_task_id 查询的话 ,是没法使用到 这个联合索引的

为了验证一下 ,我自己写了一个查询,如下:

data_process=> explain analyze select * from dpp_process_service_task where ecs_task_id='d9fee7c3438d4f2b9246c772d0c31bff';
                                                                  QUERY PLAN                                                                  
----------------------------------------------------------------------------------------------------------------------------------------------
 Gather  (cost=1000.00..123278.01 rows=1 width=135) (actual time=5012.319..5046.376 rows=0 loops=1)
   Workers Planned: 2
   Workers Launched: 2
   ->  Parallel Seq Scan on dpp_process_service_task  (cost=0.00..122277.91 rows=1 width=135) (actual time=4966.088..4966.089 rows=0 loops=3)
         Filter: (ecs_task_id = 'd9fee7c3438d4f2b9246c772d0c31bff'::text)
         Rows Removed by Filter: 1533831
 Planning Time: 0.074 ms
 Execution Time: 5046.405 ms
(8 rows)

从上面的执行计划中 我们可以看到 Seq Scan ,也就是 使用了 全表扫描的方式,所以执行耗时也高,查询耗费达到了5s;

解决问题

解决问题的方案 其实也简答,只要在 这种表上面 加一个ecs_task_id 索引就可以了

优化 过后的:

image.png

image.png

明显从CPU 和IOPS 上都得到了很明显的改善

总结反思

什么地方引起的问题

由于定位了问题,也知道了出现问题的SQL,那我就去找了下 出现问题的地方,我查了下项目中使用到了ecs_task_id 查询dpp_process_service_task 表的地方,发现了引发问题的代码:

@Override
@Transactional
public void saveServiceTask(List<DataProcessServiceTask> ecsTasks) {
    for (DataProcessServiceTask ecsTask : ecsTasks) {
        //check exist
        DataProcessServiceTask serviceTask = serviceTaskMapper.selectById(ecsTask.getEcs_task_id());
        if (serviceTask == null) {
            serviceTaskMapper.insert(ecsTask);
        } else {
            ecsTask.setCreate_ts(serviceTask.getCreate_ts());
            ecsTask.setUpdate_ts(serviceTask.getUpdate_ts());
            updateEcsTask(ecsTask);
        }
    }
}

在保存这个dpp_process_service_task 的时候 ,进行了一次查询 判断是的存在,如果存在就插入,不存在就更新,为什么是这个逻辑,是因为ecs_task_id 这个ID,是平台调用K8S 接口部署服务,返回的Pod的ID,而这个方式 出现在 同步服务每个Pod的状态和伸缩服务Pod数量的时候 使用的,所以调用的很平凡,出现了越来越慢的情况,是因为dpp_process_service_task 这个表里面的数据量越来越多,我查询了一下 现在已经五百多万的数量了,所有查询会导致如此的耗时,最近一段时间 平台的服务 从AWS 的ECS和Fargate 中 逐渐 迁移到了 自建的K8S 集群中,所以导致托管的服务数量 越来越多

分析下根本原因问题

dpp_process_service_task 产生了 几百万的数据,但是平台的服务大概一百多个,是因为我在的数据处理平台,数据服务会更加服务的任务数量进行伸缩服务的Pod,就会导致 服务pod 会被频繁的拉起和关闭,但是 对比K8S 来说 每个Pod的ID 肯定是不一样的,所以才导致 历史的数据 越来越多

后面我做了优化,只保留近一个星期的Pod历史,供查询使用,解决了 此表会产生大量的数据问题;

参考信息

1:developer.aliyun.com/article/522…

2:aws.amazon.com/cn/premiums…

3:www.postgres.cn/docs/11/pgs…