美文网首页面试
抽丝剥茧之JVM-线程堆栈

抽丝剥茧之JVM-线程堆栈

作者: 大方一号 | 来源:发表于2018-10-16 16:39 被阅读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

    三克油

    • 希望本文能给各位道友提供一些帮助，答疑解惑。


    相关文章

      网友评论

        本文标题：抽丝剥茧之JVM-线程堆栈

        本文链接：https://www.haomeiwen.com/subject/fmwfzftx.html

        延伸阅读

        深度阅读

        • 您也可以注册成为美文阅读网的作者，发表您的原创作品、分享您的心情！

        栏目导航

        热点阅读

        面试

        关于我们|服务条款|联系我们|抽丝剥茧之JVM-线程堆栈|投稿指南|网站地图|RSS订阅|排版工具|手机版

        提供经典美文摘抄,优美散文欣赏,现代诗歌精选,短篇小说,心情随笔,表白情书范文,故事会在线阅读欣赏

        Copyright © 2014-2023 Haomeiwen.com All Rights Reserved. 好美文阅读网 版权所有

        备案信息：桂公网安备 45052102000051号 · 桂ICP备13007215号-3

        本站所收录作品、热点评论等信息部分来源互联网，目的只是为了系统归纳学习和传递资讯

        所有作品版权归原创作者所有，与本站立场无关，如不慎侵犯了你的权益，请联系我们告知，我们将做删除处理！