cpu分析利器 — async-profiler

简介

async-profiler是一款采集分析java性能的工具,翻译一下github上的项目介绍:

async-profiler是一款没有Safepoint bias problem低开销java采集分析器,它利用HotSpot特殊的api来收集栈信息以及内存分配信息,可以在OpenJDK,Oracle JDK以及一些其他的基于HotSpot的java虚拟机。async-profiler可以追踪以下几种事件:

  • cpu周期
  • 硬件和软件性能计数器,例如高速缓存未命中,分支未命中,页面错误,上下文切换等
  • Java堆中内存的分配
  • 锁尝试,包括Java对象监视器和ReentrantLock

使用方法

首先下载async-profiler,github主页(https://github.com/jvm-profiling-tools/async-profiler)上有已经编译好的文件,找到对应的平台下载即可

image

基本用法

下载好的文件解压后,有一个profiler.sh脚本,运行脚本即可对java进程进行cpu分析,例如java进程id为1232

<pre data-tool="mdnice编辑器" style="margin: 10px 0px; padding: 0px; border-radius: 5px; box-shadow: rgba(0, 0, 0, 0.55) 0px 2px 10px;">./profiler.sh start 1232 ./profiler.sh stop 1232 </pre>

或者可以用-d指定剖析的时间(秒)

<pre data-tool="mdnice编辑器" style="margin: 10px 0px; padding: 0px; border-radius: 5px; box-shadow: rgba(0, 0, 0, 0.55) 0px 2px 10px;">./profiler.sh -d 30 1232 </pre>

执行完成后会输出采集的信息:
image

通常我们会用更加直观的火焰图来绘制输出的信息,使用参数-f {$file_name}.svg

<pre data-tool="mdnice编辑器" style="margin: 10px 0px; padding: 0px; border-radius: 5px; box-shadow: rgba(0, 0, 0, 0.55) 0px 2px 10px;">./profiler.sh -d 30 -f ./nacos.svg 1232 </pre>

命令执行完成后会生成一个svg格式的文件,用浏览器打开

image

火焰图怎么看?可以参考阮一峰的文章

《如何读懂火焰图》 http://www.ruanyifeng.com/blog/2017/09/flame-graph.html

简单来说:x轴是抽样数,x轴越长说明被这个方法被抽样的次数越多,消耗cpu时间也越长 y轴是栈的深度,通常越往上越细,如果发现往上有一个平顶,且平顶很宽,则说明它可能有问题,消耗cpu时间较多。

其他参数介绍

  • -e event

event 可选参数用这个命令来查看

<pre data-tool="mdnice编辑器" style="margin: 10px 0px; padding: 0px; border-radius: 5px; box-shadow: rgba(0, 0, 0, 0.55) 0px 2px 10px;">./profiler.sh list list 1232 </pre>

输出样例:

image

event 默认为cpu,也可以用alloc来查看内存分配

<pre data-tool="mdnice编辑器" style="margin: 10px 0px; padding: 0px; border-radius: 5px; box-shadow: rgba(0, 0, 0, 0.55) 0px 2px 10px;">./profiler.sh -e alloc -d 30 -f ./nacos-alloc.svg 1232 </pre>

image

lock查看锁情况:

image

其他的模式这里就不一一尝试,用的最多的还是cpu模式。

  • -i N 设置采样频率,默认是10ms,可使用msuss作为单位,无单位默认为纳秒,如

<pre data-tool="mdnice编辑器" style="margin: 10px 0px; padding: 0px; border-radius: 5px; box-shadow: rgba(0, 0, 0, 0.55) 0px 2px 10px;">./profiler.sh -i 500us -d 30 </pre>

  • -j N 设置栈采样深度

  • -o fmt 设置输出格式:可选的有 summarytracesflatjfrcollapsedsvgtree,最常用的是svg

更多命令可参考async-profiler github主页

一次网关性能压测实例

笔者有一次在压测全链路异步网关时,RPS在2000左右,始终上不去,cpu消耗比较高,于是使用async-profiler进行cpu剖析,生成的火焰图如下

image

可以看到这里有个宽又深的栈,它消耗了很多cpu,限于图像大小,再往上拉,看下这块到底是什么

image

从类名就能看出是log4j,猜测是代码某处打日志过于频繁导致,找到打日志的地方后先去掉日志,压测了一下,果然RPS提升到了5000,一处小小的日志竟有如此大的影响。

原理介绍

看到这里相信你应该会用async-profiler来进行cpu剖析了,如果感兴趣可以了解下async-profiler实现的原理,这块有一篇文章介绍的很详细,可以参考

《JVM CPU Profiler技术原理及源码深度解析》 https://mp.weixin.qq.com/s/RKqmy8dw7B7WtQc6Xy2CLA

简单总结一下:

  • cpu profiler实现一般有两种方案:(1)Sampling,采样(2)Instrumentation,埋点;采样对性能损耗较小但没那么准确,埋点(类似AOP)精准但性能影响大
  • Sampling采样只能在Safe Ponit处采样,会导致统计结果偏差,也就是开头说的Safepoint bias problem,例如某些方法执行时间短,但执行频率高,正真占用了cpu,这部分如果Sampling的采样频率不能足够小,可能就采样不到,但采样频率过高又会影响性能,这就是一般的基于采样的cpu profiler的缺点
  • async-profiler是基于采样实现的,但它又没有Safepoint bias problem,它是通过一种叫做AsyncGetCallTrace的方式来采样,这种采样不需要在安全点处采样,但这个函数不是那么容易就调用到的,需要使用一些技巧(黑科技)的方式来获取

正是第三点原因我才写了这篇文章来推荐这款cpu分析利器,比如我用了一款其他的分析器(uber-common/jvm-profiler)来分析上面网关的cpu,得出了如下的火焰图

image

如果是这样,完全没法找到问题。而且阿里开源的Arthas中的cpu分析也是使用的async-profiler。所以你不试试吗?

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 220,458评论 6 513
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 94,030评论 3 396
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 166,879评论 0 358
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 59,278评论 1 295
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 68,296评论 6 397
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 52,019评论 1 308
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 40,633评论 3 420
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 39,541评论 0 276
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 46,068评论 1 319
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 38,181评论 3 340
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 40,318评论 1 352
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 35,991评论 5 347
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 41,670评论 3 331
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 32,183评论 0 23
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 33,302评论 1 272
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 48,655评论 3 375
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 45,327评论 2 358

推荐阅读更多精彩内容