引子
正值周末,娃儿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的问题,相信以后的再有这样的情况会从容一些。因为经验不足,文章中也有很多不足的地方,欢迎指出;如果觉得有用,也欢迎点赞鼓励。
成为一名优秀的程序员!