问题场景
记一次线上事故排查过程,事故的根本原因是慢SQL 查询。但线上问题的情况以及监控工具指标表现,并没有直接指向慢SQL 的问题,排查的过程值得记录和反思。
线上事故
系统使用人员反馈系统的操作卡顿或者不可用,数据列表查询有问题,后端请求响应非常慢。
初步问题排查分析
首先,第一反应应该是 web-server 出问题或者 mysql-server 出问题。比如CPU打满或者内存打满,导致的服务不可用。
通过监控工具查看应用服务器的指标、JVM指标以及数据库服务器CPU、磁盘的指标,都处于正常范围。
然后,猜想是程序、功能方面的问题,通过查询mysql 状态,并没有发现有查询的慢SQL。查询JVM线程,没有突增。
那么问题是出现在哪呢?
问题排查分析plus
上述的基础指标排除完毕,那就尝试看是否有并发锁等待、事务死锁、mysql 死锁的情况。
线程dump
通过dump JVM线程,发现有很多线程等待,前端请求线程在调用getConnection()时候,阻塞了。
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0a9d2f48> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at com.alibaba.druid.pool.DruidDataSource.pollLast(DruidDataSource.java:1487)
at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1086)
at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:953)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:931)
Insight getConnection()
DruidDataSource 实现线程池的机制是典型的生成者、消费者模式,通过类似BlockingQueue 来实现连接池的管理。
通过分析,是因为持有数据库连接的线程一直占用连接,导致其他需要和数据库交互的请求线程等待。这样的结果造成了系统的JVM CPU和堆栈都是正常情况,但是服务不可用。
同时,由于应用服务是受制于数据库连接池maxActive 的限制,并不会无限制创建mysql connection,导致数据库的IO链接也处于正常范围。
那么是什么请求一直在占用有限的connections?
private DruidConnectionHolder pollLast(long nanos) throws InterruptedException {
for (;;) {
if (poolingCount == 0) {
try {
long startEstimate = estimate;
// 如果连接池的连接都在工作,那么就需要等待
estimate = notEmpty.awaitNanos(estimate); // signal by recycle or creator
notEmptyWaitCount++;
notEmptyWaitNanos += (startEstimate - estimate);
} catch (InterruptedException ie) {
notEmpty.signal(); // propagate to non-interrupted thread
} finally {
notEmptyWaitThreadCount--;
}
}
// 从连接池获取空闲的连接,并标记
decrementPoolingCount();
DruidConnectionHolder last = connections[poolingCount];
connections[poolingCount] = null;
return last;
}
}
原来是update
通过导出mysql 慢查询日志,发现竟然有超长执行时间的update语句。
在一开始的排查过程中,只关注事故的表象,排查select 慢sql并没有问题,导致排查走了弯路。
UPDATE `orders` SET `order_carrier_tel`='xxx-xxx-5501' WHERE `order_carrier_name`= 'xxx';
由于昨天新上的编辑功能,update 的where 条件没有索引,导致全表扫描,形成慢sql。
总结
- 敬畏每一次上线。对于关键系统的code review 是不可缺失的,一次的疏忽或者冷门功能点的问题,都会导致线上的事故。
- 90%的问题是出在数据库交互过程中。平时的代码编写,SQL编写一定要慎重。只有面对线上环境的请求和庞大的数据量时,才是真正的考验。