性能测试三十七：线程死锁和阻塞

Posted 2021-02-14 malinalian

一、线程死锁

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

 

接口：http://localhost:8080/PerfTeach/DeadServlet

因为要出现线程死锁至少要2个用户，所以用3个并发，永远跑

TPS：

响应时间

使用jstat -gcutil查看，JVM正常

 

使用dstat -tcdlmnsygr查看，cpu没什么压力

 

通过浏览器访问接口，没有响应

 

jvisualvm查看

 

jstack查看：使用jstack把堆栈日志打印到a.log里面

打开直接翻到最后，第8、4、7个线程出现死锁，并且会在下面把这三个线程拿出来打印

出现死锁的位置和原因：

所以是线程7锁定了资源，然后线程8和4在等待线程7解锁

看一下代码：出现了嵌套锁

 

 

现象：出现死锁后，tps降为0，压力测试工具无法得到服务器的响应，服务器硬件资源空闲，通过jvisualvm去查看线程情况，至少两个线程一直处于红色的阻塞状态
死锁经常表现为程序的停顿，或者不再响应用户的请求。从操作系统上观察，对应进程的CPU占用率为零

 

解锁办法：重启tomcat

 

定位方法：通过jvisualvm或者jstack，进行线程dump，对线程状态进行分析,获取到哪行代码导致的死锁，如：

Found one Java-level deadlock:
http-bio-8080"-exec-162":
waiting to lock monitor 0x0818abac (object 0x84b40ad0, a com.lee.domain.Order),
which is held by ""http-bio-8080"-exec-158"
""http-bio-8080"-exec-158":
waiting to lock monitor 0x08188cd0 (object 0x84b3bc48, a com.lee.domain.Order),
which is held by ""http-bio-8080"-exec-162"

Java stack information for the threads listed above:

 

死锁一般解决思路：
1、避免嵌套加锁
2、减小锁粒度，锁越少越不容易发生死锁

 

二、线程阻塞 

 

线程阻塞问题-log4j日志级别问题
接口：http://localhost:8080/PerfTeach/Block?userId=1

30个并发永远跑，dstat监控起来：dstat -tcdlmnsygr --disk-util

从资源上看，问题不大

TPS：550左右

响应时间：46左右

一般在项目中发现响应式时间长，监控一下线程

右上角Dump，多Dump几次，这里Dump3次，然后把3个快照里面的内容分别复制3个文本里面，直接ctrl+f搜BLOCKED

 

 

代码里面这一行在打印日志

 log4j代码里面有锁

 

解决方案：

1、还是用log4j，但是把日志打印级别提高，在代码里面减少不必要的日志打印输出

2、换其他日志组件如：log4j2、logback

 

log4j.xml中设置的日志级别，程序会打印在此级别之上日志
Error、Warn、Info、debug，级别越低，日志越多

cd /home/apps/app-PerfTeach/PerfTeach/WEB-INF/classes/

vi log4j.xml

默认打印级别是debug，改为error

 

重启tomcat

 

 还是30个并发，永远跑

 

看一下tomcat下的日志

cd /home/server/tomcat-PerfTeach01/bin/D:/

tail -f output.log

全是error级别的

TPS：900左右

响应时间：40左右

和刚才相比，TPS和响应时间都有明显的提升，由于配置比较低，这里提升不明显，真实公司里面的配置，最少提升2--3倍

 

从线程监控看，阻塞情况减少很多了，这个阻塞情况是因为打印error的日志

 

线程问题排查流程：
1、做线程dump
2、在dump文件中搜索关键字"BLOCKED"、"TIME_WAITTING"，查看每种状态的count数量
3、按照上述关键字搜索，查看跟本系统有关的业务代码堆栈信息