500个线程运行串行原因排查

场景：项目中有业务需要开启500个线程执行，需要证明有500个线程在执行。用的是一台128核的电脑。服务用docker启动的。所以理论上应该是要有128个线程并行执行的。

 

目录

一.证明有500个线程在执行(会发现并行度很低)

1.用top命令监控进程内的线程运行情况

二.排查没有并行的原因

1.通过日志排查（只证明了并发，但找不到无法并行的原因）

2.用jconsole排查(只证明了确实有用线程池创建了500个线程)

 3.用jvisualVm排查(可以看出多个线程间基本是串行的)

 4.验证是否业务代码才会导致串行，如果创建线程执行没有逻辑的代码是否串行(主要怀疑是否会是服务器问题)(证明服务器确实可以有128个线程并行)

5.验证是否是日志导致的(日志可能有影响，但不是核心问题)

6.通过dump线程堆栈信息进行排查(以此找到了串行的原因)

6.用top再次验证并行度（并行上去了，但因网络io问题会存在波动）

三.其他问题

四.进程内的线程运行情况shell脚本(top -H -p无法使用时可用，不确定是否所有linux下都试用。)

---

一.证明有500个线程在执行(会发现并行度很低)

1.用top命令监控进程内的线程运行情况

        1).执行 docker container top ${容器名称} 命令，查到服务在宿主机对应的进程pid.此处对应的进程pid 为 20575。第一个进程是sh 命令,找java开头的。

         2).然后执行 top -H -p ${pid} 观察进程内的线程运行情况，可以看到线程数与3278，但是running的线程2-8跳动.并行度太低。(有些服务器top 是没有-H -p参数的，比如alpine服务器。文章末有提供shell脚本进行统计)

二.排查没有并行的原因

1.通过日志排查（只证明了并发，但找不到无法并行的原因）

        就是各种打日志，调整线程池参数。证明有多个线程，也都有在并发执行。但这样却找不到没有并行的原因。

2.用jconsole排查(只证明了确实有用线程池创建了500个线程)

        1). java 启动参数增加如下配置

-Dcom.sun.management.jmxremote
-Dcom.sun.management.jmxremote.port=8088 
-Dcom.sun.management.jmxremote.ssl=false 
-Dcom.sun.management.jmxremote.authenticate=false

如

java -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=8088 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -jar boot.jar

        2).打开cmd 执行 jconsole 。(前提有装jdk 并配有环境变量。）远程进程配置 ${ip:port}.然后点击连接。

         3).看线程标签页，搜索业务，发现业务线程确实创了500个。到此仅是证明有创建了500个线程。

 3.用jvisualVm排查(可以看出多个线程间基本是串行的)

        1).怎么远程连接就不详细说了。和jconsole类似。都是连接同一个jmx端口。连接上后通过jvisualVm线程标签页可以看到多个线程基本是串行交替运行的。如下图所示

 再来一张清晰点的，但是只是模拟，并非实际场景

 4.验证是否业务代码才会导致串行，如果创建线程执行没有逻辑的代码是否串行(主要怀疑是否会是服务器问题)(证明服务器确实可以有128个线程并行)

        1).执行如下代码

public static void main(String[] args) {
    ThreadPoolExecutor executor = new ThreadPoolExecutor(128, 128, 0, TimeUnit.SECONDS, new ArrayBlockingQueue<>(100), new CustomizableThreadFactory("业务线程"));
    for (int i = 0; i < 128; i++) {
        executor.submit(() -> {
            while (true) {
                System.out.println(Thread.currentThread().getId());
            }
        });
    }
}

        1.)用 jvisualVm 观察线程发现依然是串行的。(有点怀疑人生了)
        2.)代码中还是执行了一行System.out.println的,去掉日志的打印试了下，发现确实并行。        

5.验证是否是日志导致的(日志可能有影响，但不是核心问题)

        1). 通过spring配置把log4j的相关日志全关闭了（logging.level.root=off）,并把项目里的所有System.out.println全删掉.然后再次用jvisualVM 观察,发现并行度依然没上去

备注：如果是日志问题后期可以考虑根据线程分配不同的日志文件或者把写日志改为异步。

6.通过dump线程堆栈信息进行排查(以此找到了串行的原因)

        1).在运行中可以点击jvisualVm的线程dump，dump出当前的堆栈信息

        2).分析堆栈信息发现大多数线程都被阻塞在JTSFactoryFinder.getGeometryFactory方法.这个方法加了锁，业务代码中每次循环都会调用这个方法非常多次。每次调用都会阻塞其他线程从而导致串行。

         3).分析JTSFactoryFinder.getGeometryFactory方法发现就是返回一个无状态单例。于是把这方法返回的对象抽取一个全局对象。所有调用的地方都获取这个全局对象。

        4).再用jvisualVm 观察发现并行度明显提高了。

        5).然后再次dump 线程堆栈，这时线程主要都是阻塞在网络io相关的地方。

6.用top再次验证并行度（并行上去了，但因网络io问题会存在波动）

        用top -H -p ${pid} 查看进程运行情况，发现running数在0-120间跳动，无法一直处在128的并行。猜测会跳动的原因应该是因为网路io的原因，被其他服务阻塞了。想进一步提高并行概率估计就得从其他服务下手了。

三.其他问题

500线程下的一些其他问题主要是dubbo线程耗尽，druid获取不到连接之类的其他问题。主要都是通过改dubbo、druid、mysql配置解决。

四.进程内的线程运行情况shell脚本(top -H -p无法使用时可用，不确定是否所有linux下都试用。)

#!/bin/bash

while(true)
do
	total=0
	running=0
	sleeping=0
	stoped=0
	zombie=0
	#$1 是进程id
	for thread in `ls /proc/$1/task`
	do
		#在apline里使用total=$[total+1] 会统计不出来
		let total+=1
		stat=$(awk '{print $3}' /proc/$1/task/$thread/stat)
		case $stat in
		R)
			let running+=1;;
		T)
			let stoped+=1;;
		S)
			let sleeping+=1;;
		Z)
			let zombie+=1;;
		esac
	done
	echo "总线程数是$total"
	echo "运行中线程数是$running"
	echo "睡眠线程数是$sleeping"
	echo "停止线程数是$stoped"
	echo "僵尸线程数是$zombie"
	sleep 2
done