抽丝剥茧之JVM-线程堆栈
2018-10-16 本文已影响382人
大方一号
分享是一种精神，是加深理解最好的方式，没有之一！
前言
本次分享以及后续章节旨在提升同学们对JVM的认知度，hold住她！干！
1、解决一般线上JVM故障(cpu,内存,gc等问题）
2、了解JVM基本结构和原理，以及常用的性能优化手段
3、掌握常用的JVM-分析工具
4、十分钟定位问题
开车了！
常用工具
线程堆栈
线程堆栈也称线程调用堆栈，是虚拟机中线程（包括锁）状态的一个瞬间快照，即系统在某一个时刻所有线程的运行状态，包括每一个线程的调用堆栈，锁的持有情况。
线程堆栈一般包含以下关键信息
- 线程名字，id，线程的数量等
- 线程的运行状态，锁的状态
- 调用堆栈 即是所执行的方法，落地到具体的代码行数
so！借助堆栈信息可以帮助分析很多问题，如线程死锁，锁竞争，死循环，large线程耗时操作等等。在多数情况下，无须介入代码亦可对系统进行分析和故障定位！
线程堆栈一般可解决CPU相关的如下问题
- 系统无缘无故的cpu过高（区分us和sy)
- 系统挂起，无响应
- 性能瓶颈（如无法充分利用cpu等）
- 线程死锁，死循环等
- 线程数量太多导致的内存溢出
vmstat pidstat 亦可分析CPU消耗情况，结合线程堆栈来分析更佳，但是定位问题还是优先分析dump文件，本文先忽略......
如何分析进程or线程堆栈？
- 常龟操作
获取进程id
jps
获取进程堆栈
jstack –l <pid> >> thread.dump
根据进程pid获取线程tid详情
top -H -p <pid>
根据线程tid 搜索进程堆栈
cat thread.dump | grep tid...
查询进程对应的线程数
cat /proc/进程id/status | grep Threads
- jps -v ( 传递给JVM的完整参数)
10754 identify-webapi-0.0.1.war -verbose:gc -Xloggc:/data/program/cn.xxx/xxx-api/0.0.1/gc.log -
XX:+PrintGCDetails -XX:+PrintGCDateStamps -
XX:+HeapDumpOnOutOfMemoryError -
XX:HeapDumpPath=/data/program/cn.xxx/xxx-webapi/0.0.1/java.hprof -
-Xms2g -Xmx2g
-XX:MetaspaceSize=38m -XX:MaxMetaspaceSize=380m
XX:+UseConcMarkSweepGC -XX:CMSMaxAbortablePrecleanTime=5000 -XX:+CMSClassUnlo
28985 Jps -Dapplication.home=/xx/xxx/java8 -Xms8m
上述JVM参数 其实内容丰富
1、gc -Xloggc....配置了gc 日志的路径
2、XX:PrintGCDetails,就开启了详细GC日志模式，文件内容比较冗杂，亦可结合jvisualvm来分析。
3、XX:+HeapDumpOnOutOfMemoryError :JVM在遇到OOM(OutOfMemoryError)时生成Dump文件，同时可以指定文件路径
4、-Xms2g -Xmx2g 启动堆内存和最大堆内存一样
5、-XX:MetaspaceSize=38m -XX:MaxMetaspaceSize=380m 元空间初始值和最大值
6、UseConcMarkSweepGC：使用了cms垃圾收集器
........
可视化工具jvisualvm 初探...
$jps -l
9904 org.jetbrains.jps.cmdline.Launcher
9905 com.xxx.xxx.xxx.router.xxxApp
9878 org.jetbrains.idea.maven.server.RemoteMavenServer
......略.
VS
-
线程堆栈可视化截图
上图重点关注的细节
- 线程个数
- 线程状态
- 线程命名
- 线程运行时间
.....
ps：本次重点不在可视化工具，如果能理解JVM-堆栈内容，其实比可视化工具更强大，jvisualvm就是dump文件的的阉割版。
案例分析一 新手入门
线上CPU负载飙升到100%以上
top监控结果
$top
top - 11:37:34 up 100 days, 23:25, 1 user, load average: 0.75, 0.70, 0.63
Tasks: 32 total, 3 running, 29 sleeping, 0 stopped, 0 zombie
Cpu(s): 55.6%us, 3.0%sy, 0.0%ni, 41.3%id, 0.0%wa, 0.0%hi, 0.0%si, 0.1%st
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
18001 root 0 -20 5631m 4.0g 102m S 93.2 49.6 1024:13 java
其中CPU负载较高 达到了93% 最近十五分钟的负载都在60+%
- tips: CPU 负载升高大部分表现为us用户线程或者sy系统线程占比太高
本例us值高达 55.6% ，表示运行的应用程序消耗了大部分的 CPU，也就是说应用里面有所谓的大线程:large-thread
如何找到它？
根据常龟操作
1、jps定位到进程pid
2、根据进程id定位线程列表并根据cpu排序
$ top -H -p 10754
如图 表明线程tid=11979 cpu占比达99% 内存 60% ，
3、进制转换，11979是10进制数，在线程dump中线程id是十六进制，需要进一步转换
linux 终端 printf "%x\n" 11979 -> 2ecb -> 0x2ecb
OR
在线进制转换 十进制转换十六进制.
4、导出当前堆栈到文件中
jstack -l 10754 >> x.dump
5、搜索查询对应线程id运行明细
cat x.dump | grep 0x2ecb -A 30
结果如下
"http-nio-8848-exec-6" #31 daemon prio=5 os_prio=31 tid=0x00007ff87dae5800 nid=0x6b03 runnable [0x0000700010ef0000]
java.lang.Thread.State: RUNNABLE
at com.test.xxxx.identify.router.Looper.cpu_check(TestController.java:77)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
- 定位到具体代码-
//模拟一段死循环
Long i=0L;
while(true){
i++;
if(i==-99){
break;
}
}
- 死循环类似电路系统中的"短路"
- 上述案例是一种比较极端的情况，基友们可以拿这个来练手，寻找JVM中的"Big-Thread" 大线程
- tips：线程如果出现了大循环，亦会飙高CPU
可简单在循环体中加一句
for(....){
Thread.sleep(0);
or
Thread.sleep(1);
}
sleep(0)释放当前线程所剩余的时间片，让出CPU执行权，不要再"霸占"CPU"，这样可以让操作系统切换其他线程来执行，也可以避免太多线程"饥饿" 提升效率
案例分析二
- 线上入库上线后，CPU飙升到了100%, 用户线程us高达50%，可见有一批计算密集型的线程在run......
万变不离其宗，还是案例一中的方法 - 定位pid->定位tid->定位dump->定位代码(需要多次操作)
PID USER PR NI VIRT RES SHR S %CPU %MEM
15707 root 20 0 6213m 2.5g 7844 S 1.3 65.5
19811 root 20 0 6213m 2.5g 7844 S 1.0 65.5
19992 root 20 0 6213m 2.5g 7844 S 1.0 65.5
15693 root 20 0 6213m 2.5g 7844 S 1.0 65.5
16362 root 20 0 6213m 2.5g 7844 S 1.0 65.5
16443 root 20 0 6213m 2.5g 7844 S 1.0 65.5
19812 root 20 0 6213m 2.5g 7844 S 0.7 65.5
19814 root 20 0 6213m 2.5g 7844 S 0.7 65.5
....略上百条....
- 线程堆栈部分截取
"http-nio-8080-exec-261" #15738 daemon prio=5 os_prio=0 tid=0x00007fef60117800 nid=0x406b runnable [0x00007feefb50d000]
java.lang.Thread.State: RUNNABLE
at org.apache.ibatis.trace.TraceIntercept.replaceFirst(TraceIntercept.java:219)
at org.apache.ibatis.trace.TraceIntercept.replacePlaceholder(TraceIntercept.java:196)
at org.apache.ibatis.trace.TraceIntercept.getSql(TraceIntercept.java:172)
at org.apache.ibatis.trace.TraceIntercept.intercept(TraceIntercept.java:98)
at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)
at com.sun.proxy.$Proxy162.update(Unknown Source)
at org.apache.ibatis.session.defaults.DefaultSqlSession.update$impl(DefaultSqlSession.java:198)
at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java)
at org.apache.ibatis.session.defaults.DefaultSqlSession.insert(DefaultSqlSession.java:185)
at sun.reflect.GeneratedMethodAccessor138.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:433)
at com.sun.proxy.$Proxy130.insert(Unknown Source)
at org.mybatis.spring.SqlSessionTemplate.insert(SqlSessionTemplate.java:278)
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:57)
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:59)
at com.sun.proxy.$Proxy149.batchInsert(Unknown Source)
at cn.xxx.xxx.xxx.dao.RawDataDAO.batchInsert(RawDataDAO.java:72)
at cn.xxx.xxx.xxx.xxxx.batchInsert(RawDataManager.java:113)
at cn.xxx.xxx.xxx.xxxx.batchRawData(RawdataStorageServiceImpl.java:101)
at cn.xxx.xxx.controller.xxxxController.batchRawData(RawDataManagerController.java:60)
- 定位到代码org.apache.ibatis.trace.TraceIntercept.replaceFirst
mysql中间件链路跟踪 sql 拦截器，记录sql执行耗时rt，用来发现"慢sql".
查询一下这段sql链路跟踪代码出现的次数（多次操作)
$ grep -c 'org.apache.ibatis.trace.TraceIntercept.getSql' k1.dump k2.dump k3.dump
k1.dump:89
k2.dump:76
k3.dump:98
- 纳尼，100不到的http用户线程 cpu 能飙升到100%+？
- 拦截器sql拼接字符串处理正则+replace太剧烈
如何分析线程堆栈?
名词解释
"http." prio=1 tid=0x000000000238e800 nid=0xc940 runnable [0x00000000027af000].
| | | | | |
| | | | | +--线程占用内存地址
| | | | +-----------线程的状态
| | | +----线程对应的本地线程id号
| | +-------------------线程id
| +--------------------------线程优先级
+-------------------------------线程名称
备注：
- 线程命名很重要！
- 大线程的话 线程状态 必定为RUNNABLE
- 线程id和线程对应的本地线程id不是一个概念
线程对应的本地线程id号，是指Java线程所对应的虚拟机中的本地线程。由于Java执行的实体是Java虚拟机，因此Java语言中的线程是依附于虚拟机中的本地线程来运行的，实际上是本地线程在执行Java线程代码。 - 线程堆栈关键字 可以做很多事情
//查询tomcat-http线程数
grep -c 'http-nio-8080-exec' k2.dump
200
ps:200 是tomcat默认的最大线程数，多次堆栈查出http线程数都达到了200，此处说明max-threads有待增大...
//查询当前堆栈dubbo线程数
grep -c 'DubboServerHandler-10.3.10.110:20888' k3.dump
200
ps:200是dubbo默认的最大线程数，优化策略
dubbo线程命名方式:DubboServerHandler+ip+端口+...
//查询当前堆栈线程数
grep -c 'nid' k2.dump
537
//查询运行中的线程数
grep -c 'java.lang.Thread.State: RUNNABLE' k2.dump
228
//springboot tomcat-http线程数配置
server.tomcat.max-threads=400
//dubbo线程数配置
<dubbo:protocol name="dubbo" port="20788" threadpool="cached" threads="400"/>
锁的解读
- 线程占有一个锁的时候，线程的堆栈中会打印--locked<锁地址>
"http-nio-8080-exec-38" #908 daemon prio=5 os_prio=0 tid=0x00007fa0fc040000 nid=0x440c runnable [0x00007fa0dc35d000]
java.lang.Thread.State: RUNNABLE
at java.xxx...
....略
- locked <0x00000000937f16c0> (a java.io.BufferedInputStream)
- 线程正在等待其它线程释放该锁--waiting to lock<锁地址>
此时该段关键字waiting to lock会在线程堆栈中频繁出现 - 线程处于BLOCKED状态，通过堆栈可以获取线程对应锁相关的线程
同一把锁 locked和 waiting to lock 通常呈现一对多的情况..
同理 线程状态 也是 RUNNABLE和BLOCKED也是一对多出现..
此时应用处于激烈的锁竞争，(synchronized/lock...)cpu也有可能会飙升，当然更多的情况是系统某些请求"变得很慢".....
"processor-13" daemon prio=5 tid=0x003edf98 nid=0xca waiting for monitor entry [0x000000000825f000]
java.lang.Thread.State: BLOCKED (on object monitor)
at beans.ConnectionPool.getConnection(ConnectionPool.java:102)
- waiting to lock <0xe0375410> (a beans.ConnectionPool)
at beans.cus.ServiceCnt.getTodayCount(ServiceCnt.java:111)
at beans.cus.ServiceCnt.insertCount(ServiceCnt.java:43)
- 死锁 deadlock 堆栈内容一旦出现了 deadlock ，相关线程两个或多个会一直纠缠在一起，挂在那里一动也不动。
Found one Java-level deadlock:
=============================
Java stack information for the threads listed above:
===================================================
"com.xxx.xxx.jvm.deadlock.TestThread2":
at com.xxx.xxx.jvm.deadlock.TestThread2.fun(TestThread2.java:35)
- waiting to lock <0x00000000d77363d0> (a java.lang.Object)
- locked <0x00000000d77363e0> (a java.lang.Object)
at com.xxx.xxx.jvm.deadlock.TestThread2.run(TestThread2.java:22)
"com.xxx.xxx.jvm.deadlock.TestThread1":
at com.xxx.xxx.jvm.deadlock.TestThread1.fun(TestThread1.java:33)
- waiting to lock <0x00000000d77363e0> (a java.lang.Object)
- locked <0x00000000d77363d0> (a java.lang.Object)
at com.xxx.xxx.jvm.deadlock.TestThread1.run(TestThread1.java:20)
Found 1 deadlock.
ps ：死锁线程如果不是很消耗cpu的线程，如高浮点计算，字符串处理，正则匹配、大循环等cpu密集型线程，cpu是不会飙升的！系统也不会崩溃。它只是挂在那里！同理 mysql、oracle出现死锁也不会影响其他sql执行。
线程状态
线程堆栈分析重点关注一下关键字出现频率
Runnable：太多-> 说明系统负载合理，吞吐量高
BLOCKED ：线程阻塞，锁竞争激烈
WAITING/TIMED_WAITING： 表明大多数线程在睡觉，cpu利用率不高...
//查询堆栈中的线程状态分布列表
grep java.lang.Thread.State k2.dump | awk '{print $2$3$4$5}' | sort | uniq -c
1 BLOCKED(onobjectmonitor)
228 RUNNABLE
5 TIMED_WAITING(onobjectmonitor)
33 TIMED_WAITING(parking)
9 TIMED_WAITING(sleeping)
1 WAITING(onobjectmonitor)
253 WAITING(parking)
案例分析三
接收到告警信息，一直持续....
登录到线上
查询进程15880对应的线程数
三次cat结果如下...
cat /proc/15880/status | grep Threads
Threads: 1809 /2310 /1980
$ top
top - 17:31:49 up 84 days, 2:59, 1 user, load average: 0.59, 0.51, 0.49
Tasks: 160 total, 1 running, 158 sleeping, 1 stopped, 0 zombie
Cpu(s): 1.4%us, 34%sy, 39.1%wa
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
15880 appweb 20 0 7605m 2.5g 7136 S 57.8 64.6 854:33.19 java
- 34%sy 系统线程达到了 34% 内核线程消耗占比略偏高！
- 32.1%wa io消耗高，可能http抓包线程比较多（io先忽略)
SocketInputStream.socketRead0...屡见不鲜..
[0x0000xxxx1111] java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
说明当前应用线程间上下文切换比较严重(不算特别严重，没到崩溃边缘) --> 主要原因之一 创建了太多线程.（猜测）
- 线程堆栈分析
- 此时创建了太多线程，绝大多数都是应用线程，在不了解代码的情况下最好的解决办法就是随机浏览，根据线程命名很容易发现同一类型的线程堆栈....
不用搜索，直接查看线程dump
快捷方法 可以先搜索一下关键字 RUNNABLE
大量出现了一下RUNNABLE 线程的堆栈信息
"thread-129" #122 prio=5 os_prio=0 tid=0x00007fba682bc000 nid=0x3eee runnable [0x00007fb9ff622000]
java.lang.Thread.State: RUNNABLE
at okhttp3.RealCall.execute(RealCall.java:77)
at cn.xxx.xxx.xxx.MyClient.send(MyClient.java:129)
at cn.xxx.xxx.crawler.xxxCrawler.getDetail(FayuanCrawler.java:411)
at cn.xxx.xxx.crawler.xxxxCrawler.parseSearchHtml(FayuanCrawler.java:236)
at cn.xxx.xxx.crawler.xxxxCrawler.exec(FayuanCrawler.java:140)
at cn.xxx.xxx.service.xx.lambda$handle$0(MessageHandle.java:41)
at cn.xxx.xxx.service.MessageHandle$$Lambda$46/1501251393.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
堆栈关键字搜索次数
grep -c 'xxxxCrawler.exec' jstack.log
863
这还只是一部分....
最终定位到代码 xxxxCrawler.exec(.....
可能存在无节制的创建线程业务逻辑
Executors.newCachedThreadPool();
@RequestMapping("/start")
public String startxxxxx() {
new Thread(this::naxy).start();
return "success";
}
-
Alibaba code规范 -Java代码规范的老司机...
案例分析四
应用创建了合理的较多的线程，但是cpu使用率一直不高，吞吐量上不去！
-
应用复盘
计费kafka-消费端消息出现大量堆积，grail告警。
增大线程数4->40个，查看cpu负载 和之前变化不大
增加到100，cpu负载如故
增加到250，cpu负载略增高。
kafka消息任处于堆积中，任凭怎么折腾，cpu吞吐量上不去，干着急！ -
导出线程堆栈dump，关注一下kafka消费线程，本应用kafka的线程命名为
p-kafka-http-consumer 开头。
先查看下kafka线程数
grep -c 'p-kafka-http-consumer' kop.log
100
随便打开一个kafka消费线程堆栈
"p-kafka-http-consumer-t5-for-wodlee.visitrecord" #81 daemon prio=5 os_prio=0 tid=0x00007f39e4bf6800 nid=0x1a37 waiting on condition [0x00007f3943ffe000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at com.xxx.xxx.xxx.consumer.Looper$1.perform(Looper.java:154)
at com.xxx.xxx.kafka.consumer.Looper.performAction(Looper.java:106)
at com.xxx.xxx.kafka.consumer.Looper.loop(Looper.java:78)
at com.xxx.xxx.kafka.consumer.Looper.run(Looper.java:43)
发现大量的kafka消费线程 都处于 TIMED_WAITING (sleeping) 睡觉状态
查看处于RUNNABLE状态的 kafka线程,多次dump 发现
p-xxx-http-consumer处于运行中的kafka消费线程个数处于[0,1]之间
以上分析表明
kafka消费端，无论开启多少线程，进程中都只会有一个线程处于运行状态，其他剩余线程都在睡大觉。
- 根据堆栈信息定位到kafka客户端代码Looper类154行左右
switch (status) {
case OK:
next = LooperState.PROCESSING;
break;
case DEFER:
case SERVER_ERROR:
//表明出现了锁冲突，消费端rt 5ms左右，100个线程竞争，锁冲突的概率很高，
//这里直接用sleep 来缓解，降低cpu负载
//其实可以考虑采用CAS的方式fetch对应的offset消息
case LOCK_CONFLICT:
next = LooperState.WAITING;
break;
//.....略
actions.put(LooperState.WAITING, new StateAction() {
public LooperState perform() throws Exception {
try {
int sleepTime = 1100;
if (consumer instanceof ParallelKafkaConsumer) {
ParallelKafkaConsumer pc = (ParallelKafkaConsumer) consumer;
int alive = pc.getLooperThreadNum() - pc.getDeadThreadNum();
if (alive > 1 && alive < 5) {
sleepTime = 1500;
} else if (alive >= 5) {
sleepTime = 2000;
}
}
Thread.sleep(sleepTime);
} catch (InterruptedException ie) {
}
return LooperState.FETCHING;
}
});
kafka消费端fetch消息，如果发现当前状态为LOCK_CONFLICT，会执行一段1.5s-2s的sleep
- 解决方案，增大了kafka-bridge-server拉取数据限制，一次拉取更多的消息，减少sleep的时间等等。
MORE
三克油
-
希望本文能给各位道友提供一些帮助，答疑解惑。
