火焰图--记一次cpu降温过程

引子　　　

　　正值周末，娃儿6:30又如闹铃般准时来叫醒了我们。年前离开美菜，又回到了杭州。原本是想有更多时间陪伴娃儿，然而新的工作节奏与工作地点，让我们每天都是早上见面；这不，为了周末可以多玩一会儿，早早就过来唤醒我们。因为前几天我们就约好了周末一起放风筝。有些事儿，我以为只是随口一说，小孩子确真真的记着。

　　吃过早饭，拉着媳妇儿，领着娃，带上风筝就出门了。其实我是忐忑的，因为我也从来没有把风筝放起来过。来到草坪上，娃就拉着风筝如脱缰之马跑了起来。小孩子的幸福就这么简单，无关乎风筝能飞多高。

         　　　　　　　　　　　　　　　　　　　　　　　　

 

　　迎着暖暖朝阳，吹着徐徐春风，一下子感觉2周加班的疲惫都消散了。然而，一阵儿急促的“钉钉”声打破了难得的宁静：Warning， ***applicaiton， cpu 高于51%，持续2分钟。此服务涉及大部分单车投放操作，目前是新老并用，我们是新服务，tps不高，但业务非常重要。于是拉着还未尽兴的娃儿，回去处理问题了。当然我的内心是紧张而喜悦的，每次的故障就是一次学习的机会。

 

问题分析　　

　　既然是cpu告警，首先查看cpu最近的使用情况，一看得到两条信息：1，下图中剪头所指的地方就是促发告警的阀值，2，cpu一直在40-50%上下徘徊 。

 我想大家看到这个图也明白了：告警是正常的，目前cpu的情况很容易就会促发告警。反思一分钟：整天埋头支撑业务，连系统的如此重要指标都没有关注到。然后迅速回忆最近上线的功能，想到2月底，上线过电子锁的需求，但是系统已经无法查看2月分的cpu日志，接下来我们需要去找出问题。

 

排除内存原因

　　平时很少有处理生产环境cpu过高问题，真正碰到这样的场景还是蒙圈的。看看网上好些帖子都是说: heap 内存不足，分配内存失败，会导致cpu偏高。首先使用jstat -gcutil 查看内存使用情况，如下图，可见 新生代的区域 survivor0, survivor1,  eden 以及老生代都正常，FGC 也正常。 

 

 

jstat -gcutil 参数说明如下

　　 

重新再来

　　 遇到问题，猜是需要经验的，瞎忙是没用的，既然没经验那就一步一步来验证吧；

      1， ps -ef | grep java 找到进程id   27931

　　2,  top -H -p 9527 找到占cpu的线程

    

 

    3,  使用jstack 分别找也上面的线程的具体内容，比如第一个线程 28045。

      a,  转化线程id为16进制   printf '%x\n' 28045，输出 6d8d， 因为jstack 中线程id 是16进制的。

      b，jstack  27931 | grep 6d8d ，找到此线程

       jstack  27931 | grep 6d8d 
     "HmsKafkaPollThread-logistic_cargo_launch_consumer-CONSUMER_DEFAULT_NAME2020-04-05T09:24:19.889" #34 prio=5 os_prio=0           tid=0x00007f4211fd8800 nid=0x6d8d runnable [0x00007f419e2ef000]

     c， 再用同样的方法，发现其他几个线程也是 kafka 消费者引起的。

         jstack  27931 | grep 6da1
"HmsKafkaConsumerThread_4" #49 prio=5 os_prio=0 tid=0x00007f418822b800 nid=0x6da1 waiting on condition [0x00007f419cbe0000]

        jstack  27931 | grep 6d9f
"HmsKafkaConsumerThread_2" #47 prio=5 os_prio=0 tid=0x00007f4188228000 nid=0x6d9f waiting on condition [0x00007f419cde2000]

    4，知道问题在于消费kafka了，原来上次做电子锁需求时，为了拿到开锁结果，监听了一个kafka topic，这是一个特别核心的topic（后来听其他同事说，这是公司消息量最多的上个topic了），

随手查了下一个小时的数据26亿/h，也就是 70w/s,  如此巨大的tps, 而此服务只有两个结点，cpu维持在50%左右就不奇怪了。

 

　 到这里，我还想再深究下，到底时哪几行代码占了cpu,  那应该如何找到这些代码呢。说来真是特别巧，上周5听了测试同学的性能测试分享，后来还找时间了解了其中的火焰图（flame graph）和arthas ， 对就是“火焰图”- 今天的主角儿。关于火焰图有几个基本的知识就可以简单分析了：　　

1，y 轴表示调用栈，每一层都是一个函数。调用栈越深，火焰就越高，顶部就是正在执行的函数，下方都是它的父函数。

2 ，x 轴表示抽样数，如果一个函数在 x 轴占据的宽度越宽，就表示它被抽到的次数多，即执行的时间长。注意，x 轴不代表时间，而是所有的调用栈合并后，按字母顺序排列的。

火焰图就是看顶层的哪个函数占据的宽度最大。只要有"平顶"（plateaus），就表示该函数可能存在性能问题。

颜色没有特殊含义，因为火焰图表示的是 CPU 的繁忙程度，所以一般选择暖色调。[摘自如何读懂火焰图？]

 

    一开始看到火焰图，也是特别蒙圈的。火焰图是基于 perf 结果产生的 SVG 图片，用来展示 CPU 的调用栈，因为perf 直接生成的数据比较难看明白 ， 学习成本也非常高。，下面有几个文章特别不错，英文文档读起来不算太复杂，中文的似乎就是翻译英文文档。

   英文文档：

　http://www.brendangregg.com/flamegraphs.html , https://queue.acm.org/detail.cfm?id=2927301

   中文说明：

   http://www.ruanyifeng.com/blog/2017/09/flame-graph.html

   火焰图demo:

　https://queue.acm.org/downloads/2016/Gregg7.svg

    

　　    

火焰图实践

　　 1，clone javaFlameGraph，git 地址如下：https://github.com/saquibkhan/javaFlameGraph，

       有一个地方要特别注意下：javaFlameGraph 核心是调用 FlameGraph中的实现，如图中剪头所指的项目，要确保FlameGraph也下载了。

　　

 

 

　　 2，拉出一个节点摘掉流量，上传clone的文件。

　　 3，到上传文件的所在目录执行  ./flame-gen.sh 27931  ，等待30s, control +c 就开始生成报告了。

       

 

 

 　　4，报告为当前目录下的  flame.html ,  找开就是生成的火焰图了。如下图。

　　

      这个图是可交互的，火焰的每一层都会标注函数名，鼠标悬浮时会显示完整的函数名、抽样抽中的次数、占据总抽样次数的百分比。下面是一个例子，可以点击每个长方形获取更多详情的信息，如图，可看到有很多都是消耗都是 fastjson的 perseobject，因为我们每收到一个消息，会使用fastjson解析，过滤出指定的消息。

 

 

       

　说明下其中几个除kafka相关线程外的线程，参考文章地址：https://blog.csdn.net/clamaa/article/details/70045983

　　DestroyJavaVM：

执行main()的线程在main执行完后调用JNI中的 jni_DestroyJavaVM() 方法唤起DestroyJavaVM 线程。JVM在服务器启动之后，就会唤起DestroyJavaVM线程，处于等待状态，等待其它线程（java线程和native线程）退出时通知它卸载JVM。线程退出时，都会判断自己当前是否是整个JVM中最后一个非daemon线程，如果是，则通知DestroyJavaVM 线程卸载JVM。

　　Surrogate Locker Thread：

这个线程主要用于配合CMS垃圾回收器使用，它是一个守护线程，其主要负责处理GC过程中，Java层的Reference（指软引用、弱引用等等）与jvm 内部层面的对象状态同步。

     jaeger.RemoteReporter-QueueProcessor：

     应该是一个分布式链路跟踪的处理线程。估计是中间件团队这边的。

结语

　　因为工作的原因，很少有机会处理高tps场景下的问题，终于理性的分析了一次生产环境cpu的问题，相信以后的再有这样的情况会从容一些。因为经验不足，文章中也有很多不足的地方，欢迎指出；如果觉得有用，也欢迎点赞鼓励。

 

　　 成为一名优秀的程序员！