问题描述
有天,测试同学突然反馈系统页面查询缓慢,影响使用,我查了日志报:
druid 连接池异常 GetConnectionTimeoutException wait millis 9120, active 20, maxActive 20 creating 0
结论先行
经一系列排查,得出数据库磁盘空间满了,清掉一些磁盘文件后,数据库和服务都恢复正常,上述报错消失了。
排查思路
查服务监控
我们服务部署在公司容器云平台上,查监控服务CPU和内存都正常,不高。但当天有几次容器健康检查没通过,容器发生自动重启过,不太正常。
查数据库
因为测试库mysql是开发自己部署的,没监控和预警功能。下意识看看数据库连接情况,怕是出现锁表或大量慢sql在执行,导致druid连接池连接没释放,用processlist命令查下当前mysql最慢的耗时线程情况:
select * from information_schema.processlist order by time desc
下面对于使用该命令查询到的结果进行解读。
Id:链接mysql 服务器线程的唯一标识,可以通过kill来终止此线程的链接。
User:当前线程链接数据库的用户
Host:显示这个语句是从哪个ip 的哪个端口上发出的。可用来追踪出问题语句的用户
db: 线程链接的数据库,如果没有则为null
Command: 显示当前连接的执行的命令,一般就是休眠或空闲(sleep),查询(query),连接(connect)
Time: 线程处在当前状态的时间,单位是秒
State:显示使用当前连接的sql语句的状态,很重要的列,后续会有所有的状态的描述,请注意,state只是语句执行中的某一个状态,一个 sql语句,已查询为例,可能需要经过copying to tmp table,Sorting result,Sending data等状态才可以完成
Info: 线程执行的sql语句,如果没有语句执行则为null。这个语句可以使客户端发来的执行语句也可以是内部执行的语句
根据TIME列和STATE列分析看:有大量处于query end的事务线程, 导致线程堆积,耗时高达35秒!高耗时sql都是对同一张表做update操作。 大量query end主要是由于flush log刷新阻塞导致的, 这是考虑可能log过多,涉及到磁盘。
进到mysql所在服务器top命令查看cpu和内存正常,但执行df -h
命令发现磁盘100%, 占满了。
进入该磁盘文件夹下,查看都是mysql存放的binlog文件(binlog主要用于记录MySQL中的数据库操作,它包括DDL和DML语句(除了查询语句)。它以事件的形式记录,它是一个二进制文件。)
binlog文件是二进制文件,不能直接读取,转base64后为可读文件后,打开, 参照命令:
mysqlbinlog --base64-output=decode-rows -v --start-position=1036090025 --stop-position=1036094825 /home/mysql80/data/mysql-bin.000071 > 1.log
发现近期binlog有个最近部署的自研中间件,每隔15秒定时update一次操作,导致频繁写入binlog,再加上mysql的binlog文件夹才25G, 没多久就磁盘写慢了。
解决办法
- 删除磁盘内不用的文件,腾出磁盘空间
- 磁盘扩容足够大
- 配置binlog自动过期清理时间,或者自己写定时清理脚本
警示
- 数据库有时间一定做好监控和预警,慢sql也开一开,以后查询慢出现慢sql也容易揪出来。
- 数据库的磁盘空间给到足够大,打开和配好自动清理机制、自动清理脚本,避免数据库磁盘不够用。