记录一个因为锁粒度不当导致的问题。

场景是这样的:

线上每天会在凌晨3点定时清理数据,但是,由于没有加limit, 导致每次清理DB的IO压力就特别大,于是开发简单的改了一版:清理数据的时候加limit限制,然后循环清理。

因为时间比较紧(当前晚上就要起作用),所以没有交给测试,另外,也考虑到修改的逻辑很简单,应该不会出问题,开发就发布上线了。

结果,早上收到报警:我们的系统一直没有接收业务请求。我马上登录到机器看到我们的应用还在运行清理数据:脑海里立马想到,完了,在等锁。于是马上重启,终止清理数据的线程,一切OK。

到公司后,开始排查到底再等哪把锁,结果发现这个问题还挺有意思的。

第一步:没有找到锁冲突

来公司就开始梳理我们清理数据的流程和接收业务请求的流程,发现竟然没有出现共用一把锁的问题:

1
2
3
4
5
6
7
8
lock.writeLock().lock();
try {
while(true) {
//clean_data
}
} finally {
lock.writeLock().unlock();
}

看了代码,立马能看出来确实是这个地方的坑:

  • 因为一直持有的lock,那么其他线程肯定会被阻塞
  • 问题是,为什么发送消息的业务方会出现 timeout?

顺着lock看,看谁会访问这把锁,发现:

1
2
3
4
5
6
7
8
9
10
public consumeLogic() {

lock.readLock().lock();
try {
//check
} finally {
lock.readLock().unlock();
}
}
}

发现我们的业务消费方请求过来的时候,会去check 一些参数,这个地方会拿lock。这么看:

  • 我们的清理逻辑,会阻塞消费方的业务,因为我们一直在删数据而不释放锁
  • 那发送方出什么问题了?

先进行了一步验证,找消费方的业务看了下,确实发现消费超时,那接下来就要找发送方超时的原因了。

第二步:线程池的配置

顺着整个链路排查,发现对于我们而言,所有的请求都会经过一个线程池,立马想到:线程池满了, 消费端占用了线程池,于是导致发送方请求处理不了,超时。

1
2
3
4
5
try {
executor.execute(handler)
}catch (RejectedExecutionException e) {
logger.error("thread poll full", e);
}

幸好打日志了,马上去找日志,发现竟然没有日志。 然后看看线程池的配置:

1
executor = Executors.newFixedThreadPool(nThread, new DefaultThreadFactory("Process-Worker"));

继续看:

1
2
3
4
5
6
public static ExecutorService newFixedThreadPool(int nThreads, ThreadFactory threadFactory) {
return new ThreadPoolExecutor(nThreads, nThreads,
0L, TimeUnit.MILLISECONDS,
new LinkedBlockingQueue<Runnable>(),
threadFactory);
}
1
2
3
public LinkedBlockingQueue() {
this(Integer.MAX_VALUE);
}

好吧,这个队列竟然这么大,导致请求都会被阻塞到queue里面,而打不出任何异常。

总结

这个问题反过来看,其实不复杂,但是,在定位的时候,确实发现了几个问题:

  1. 我们的应用会定时打印统计日志。当时发现统计日志没有了。所以,第一时间怀疑CPU被占满了
  2. 排除了CPU占满之后,马上想到所有的发送方都被阻塞了,因为没有数据过来,也没有报。
  3. 于是顺着第2点的思路再找发送方和清理任务的关联,忽略了对消费方的错误观察

后面看,我们的统计日志没有是因为我们统计线程和清理线程是一个线程导致的。整个问题下来,可以总结的点有:

  1. 访问数据库一定要加limit。 如果不是历史代码里面没有limit,也不会出现后续的问题
  2. 锁的粒度一定要小:
    • 锁的资源要小
    • 锁的时间要短
  3. 关键的逻辑使用独立的线程处理,防止所有的任务都被阻塞。