多线程死锁阻塞问题分析

Posted 2021-08-30 七月的小尾巴

死锁的定义

线程死锁就是有两个线程，一个线程锁住了资源A，又想去锁定资源B，另外一个线程锁定了资源B，又想锁定资源A。两个线程都想去得到对方的资源，而不愿意释放自己的资源，从而造成一种相互等待，无法执行的情况。

这么说可能有些抽象，我们拿个案例来解释一下。

首先，我们在程序中为了数据的安全性会进行加锁。

死锁的现象

下面我们来压测一个有线程死锁现象的接口，通常情况下我们是不建议用GUI模式下运行，GUI模式进行压测的数据通常都不准确，但是这里为了方便观看并且GUI模式下可以复现这个问题。

我们将这个接口配置3个线程，并且持续执行2秒时间，我们来观看一下TPS和响应时间的数据。执行之后，我们可以看到程序执行1秒后，数据就不再更新了。

然后去查看服务器的CPU、内存、IO、网络等都没有发现异常。

下面我们用Jvisualvm工具进行查看,JVM是非常平稳的。

然后查看线程，上方有明显的提示说检测到死锁，并提示生成线程Dump获取更多信息。我们下方可以明显看到http 147、109、102他们的颜色为鲜红色，这种颜色则说明我们当前线程状态处于block状态。

下面我们查看tomcat的进程，然后使用jstack查看对应的进程ID，打印堆栈信息。
通常出现死锁问题，我们可以滑动到最底部，可以明显的查看到会显示找到一个死锁Found 1 deadlock.

由于在Linux上面，不太方便我们查看信息，我们可以将相关的信息，打印到日志文件中。下面命令指的是我们将相关的堆栈信息打印到test.log的文件中。然后我们可以将log文件下载到本地打开。

从下方图中我们可以看到日志中告诉我们线程147、109、102发生了死锁，并且下方日志中显示了每个线程中他们具体在做的事情。

下方我们来看147这个线程等，他现在正在等待锁定<0x00000000e1759890>这个内存地址，这个内存地址是16进制并且唯一的。并且147线程已经锁定了<0x00000000e1759860>这个内存地址

然后我们在来看看109的线程在做什么。109此时正在等待锁定 <0x00000000e1759878>，锁住了 <0x00000000e1759890>这个地址。可以看到109锁定的内存地址，正是147等待锁定的内存地址。

下面我们再来看看102此时正在等待锁定 <0x00000000e1759890>，锁住了 <0x00000000e1759878>这个地址。而102等待锁定的内存地址，此时正是109锁定的。
因此也解释了我们上方的死锁的定义，线程之间它们都想去得到对方的资源，而不愿意释放自己的资源，从而造成一种相互等待，无法执行的情况。

由此我们可以总结出，出现死锁后，tps降为0，压力测试工具无法得到服务器的响应，服务器硬件资源空闲，通过 Jvisualvm去查看线程情况，至少两个线程一直处于红色阻塞状态。

死锁经常表现程序的停顿，或者不在响应用户的情况。从操作系统上观察对应的CPU占用率为零。

出现死锁之后，我们关闭压力机并不能解决问题，这个和内存溢出是一样的，我们需要重启tomcat。

死锁的解决思路

1、避免嵌套加锁
2、减少颗粒度

线程阻塞的定义

在多线程情况下，如果一个线程对拥有某个资源的锁，那么这个线程就可以运行资源相关的代码。而其他线程就只能等待其执行完毕后，才能继续争夺资源锁，从而运行相关代码。

这个定义这么说，可能比较抽象，但是其实这个场景，正常我们功能测试的时候，都会测试到，下面我们来举一个非常常见的例子。

场景：

假设我们现在有一个秒杀活动的商品，那么这个商品的库存只能最后一个了，此时有3个用户同时下单购买，这里我们定义为3个线程。

1. 因为CPU可以来回切换线程，假设A线程提交订单，此时A并没有下单购买,此刻CPU切换成线程B
2. 那么此刻B线程也下单了，并且支付成功了，此时库存变成0
3. 这个时候CPU又将线程切换回A，A也支付成功了，那么此刻库存值会变成-1

当多个用户同时操作的时候，就会导致商品超出库存售卖，这个就设计到多线程模式下的数据安全问题。关于这个场景其实在工作中是非常多的，如优惠券领取，最后一个优惠券库存的时候，多个用户同时领取，是否会出现都领取成功的情况。

解决方案

出现上方这种情况下，通常我们都需要通知开发进行加锁。在多线程的情况下，如果存在修改共享数据的操作，就需要对操作步骤进行加锁，拥有锁的线程才可以执行相关代码。没有锁的线程只能等待其释放后，才有资格执行代码。

但是大家现在思考一下，加锁之后是不是就存在了一定的性能问题，加锁之后，只有锁内部的线程才能执行业务操作，其他的线程都处于等待的状态，这样就会导致出现性能瓶颈。但是这个通常都需要根据业务来决定，在某些业务上安全性高于性能。

案例分析

下面我们来看一下某个接口的数据，当我们不断加压线程，基本上在20个左右的时候，基本上tps就压不上去了，下面图中可以看到，哪怕我线程加到30，tps仍然是在1100左右。

压测过程中，我们来看一下cpu、内存、网络等数据。

1. cpu目前只压到50%左右
2. 内存使用还算平稳（这个是自己租的服务器，内存自身就比较低）
3. 网络是局域网，也是正常的
4. 磁盘读写几乎可以忽略不计

上方服务器的资源数据我们可以看到，不断加压，tps已经达到了一个瓶颈点，但是实际上我们资源并没有完全被消耗，实际上不断加压tps应该更高才对。那么这个时候，我们一般可以考虑到是否是出现了线程阻塞。

我们可以使用jvisualvm工具查看线程状态，我们可以看到压测过程中，有非常多的线程为鲜红色，鲜红色则表示未阻塞状态。

生成对dump文件查看堆栈信息，我们可以看到有很多线程处于BLOCAKED下面

下面我们可以看到有出现log4j线程阻塞问题。由于同步大量的打印日志，导致线程阻塞。有些开发非常喜欢将日志都打印出来，但是其实大量的打印日志是会影响性能的。

log4j线程阻塞问题

下面是网上找的关于Log4j的介绍：

log4j是Apche的一个开源项目，通过使用Log4j，我们可以控制日志信息输送到目的地是控制台、文件、GUI组件，甚至是套接口服务器、NT的事件记录、UNIX Syslog守护进程等；我们也可以控制每一条日志的输出格式；通过定义每一条日志信息的级别，我们能够更加细致的控制日志的生成过程。这些可以通过一个配置文件来灵活的进行配置，而不需要修改应用的代码。

Log4j的日志级别

Level	描述
ALL	各级别包括自定义级别
DEBUG	指定细粒度信息时间是最优用的应用程序调试
ERROR	错误时间可以仍然允许应用程序继续运行
FATAL	指定非常严重的错误事件，这可能导致应用程序中止
INFO	指定能够突出在颗粒度级别的应用程序运行情况的信息的消息
OFF	这是最高级别，为了关闭日志记录
TRACE	指定细粒度比DEBUG更低的信息事件
WARN	指定具有潜在危害的情况

级别越低，日志越多：ALL > DEBUG > INFO > WARN > ERROR > TATAL

关于log4j的处理方案：

1、介绍代码中没有必要的输出
2、根据公司项目情况，更高log4j的等级，改成error，降低大量打印日志造成的线程阻塞情况
3、如果由于公司项目原因，有些公司如担心线上出现问题，方便排查，必须要打印info日志，可以考虑更换其他日志组件，如log4j2、logback等，log4j2为异步日志输出。

线程阻塞问题排查流程

1. 做线程dump
2. 在dump文件中搜索关键字"BLOCK”、”TIME_WAITING",查看每种状态的count数量
3. 按照上述关键字搜索，查看跟本系统有关的业务代码堆栈信息