背景

某日晚上9点钟,收到大量告警通知与邮件,反应线上服务有大量延迟与异常。经过简单定位,发现是我负责的服务出现的异常。因此开始了紧张刺激的bug排查之旅...

BUG排查过程

初见端倪——临时方案快速解决

首先我看了下服务的CPU与内存,发现都出现了激增的情况。观察异常日志时,发现有很多数据库操作的异常,经过确定发现是消费某个MQ的异常。
image.png
同时同事也反馈MQ出现了大量堆积现象。经询问得知当天晚上有账号迁移任务,导致有数万条请求会被放入消息队列中。
既然核心的原因是它,因此快速的将该队列与交换机的绑定关系解除并重启服务,果然延迟与异常都没有了,问题得到了临时性的解决。然后也就安心的去睡觉了(实在太累了...不想继续查了...)

疑云重重——深入考察原因

第二天来到公司通过日志开始深入排查。通过慢查询日志发现了有一个更新SQL执行的时间平均长达40多秒。
image.png
仔细一看...果然,没加索引!好吧,非常尴尬,这个方法也确实是消费MQ时需要调用的方法,问题似乎找到了?等等似乎还是有哪里不太对。

  1. 因为没加索引的这张表是一张不算很重要的表,其他很多的写操作都不涉及该表,为啥这些请求都超时异常了呢?
  2. 虽然update会锁表,但是由于InnoDB的快照读以及MVCC机制,不应该查询也出现异常。
  3. MQ的消费没有配置成多线程消费,慢更新的操作最多让消费的速度变慢,但是不应该影响到整个服务异常。

好吧...事情似乎并不简单...好像思路也都堵住了?我陷入了疑惑。

峰回路转——找出真相

在我疑惑时,突然想到项目是接入skywalking的,看看skywalking说不定能找到答案?
image.png
可以看到由于没加索引,Sql的执行时长高达20s。不过这不是关键,令我震惊的是上边的 SpringAsync。这个慢查询操作竟然是异步的?!跟着代码我终于找到了罪魁祸首...
image.png
这个操作使用了 @Async 注解,如果不指定线程池,@Async会使用默认的线程池 SimpleAsyncTaskExecutor ,于是我去翻了下源码:

	public void execute(Runnable task, long startTimeout) {
		Assert.notNull(task, "Runnable must not be null");
·               // 如果进入节流状态
		if (isThrottleActive() && startTimeout > TIMEOUT_IMMEDIATE) {
			this.concurrencyThrottle.beforeAccess();
			doExecute(new ConcurrencyThrottlingRunnable(task));
		}
               // 默认执行任务
		else {
			doExecute(task);
		}
	}

	protected void doExecute(Runnable task) {
                // 每个任务都会创建一个线程
		Thread thread = (this.threadFactory != null ? this.threadFactory.newThread(task) : createThread(task));
		thread.start();
	}

可以看到SimpleAsyncTaskExecutor会为每个任务都创建一个线程,当时MQ堆积了上万的请求,每次消费都会开启一个线程去执行慢查询。因此也就导致了线程数激增,内存消耗变大。
image.png
虽然如此,但是服务也并没有OOM呀(估计再运行一段时间就会了)。那为什么整个服务都会崩溃呢?其实也很简单...服务的数据库连接池默认最大活跃线程池数为100,由于源源不断的有线程再执行慢更新的操作,因此正常的Sql全部受到了影响。日志也的确验证了我的这个猜想:
image.png
根据日志我们可以看到由于长时间未响应结果(慢查的时间太长了),数据库连接池直接断开了连接。

至此我们终于明白了事情的前因后果,我总结下:

  1. 由于数据库没有加索引导致了出现了慢更新的操作。
  2. 由于慢更新的操作使用了@Async注解,导致源源不断的创建线程,最终反映到服务上就是CPU,内存激增。
  3. 由于大量数据库连接被满更新的操作占用了,最终导致正常的Sql无法运行,进而导致整个服务的崩溃。

痛定思痛——总结教训

  1. 数据库一定要建立合适的索引,尤其是数据量很大的表,如果整表锁住后果不堪设想。
  2. 对于MQ消费的任务,没有必要使用异步,因为MQ本身就已经做到了削峰,异步。再使用异步完全是多此一举。(当然也要根据实际业务场景)
  3. 使用@Async时,尽量不要使用默认的线程池。阿里规范里也是规定了不要使用默认线程池,因为默认线程池很容易因为这种bug导致OOM异常。

最后

说实话解决这次bug还是跌宕起伏的,再刚接到这个bug时,我其实是懵逼的...好歹周围有其他小伙伴的帮忙,快速响应解决了问题,否则影响会更严重。当然,经过这一遭,也感觉自身也提高了不少,总结经验少踩一些坑才是真正的精华。

Q.E.D.


做一个永不秃头的程序猿