手把手教你使用 Btrace 定位应用热点

前言

前段时间笔者对一个 Java 类型的项目做性能测试,发现应用 CPU 使用率很高,TPS 无法满足需求,只能通过使用性能问题定位的利器—— Btrace 来获取方法调用的平均耗时与单笔交易执行次数,从而定位热点方法,快速定位问题。下面就为大家介绍一下笔者在实际中使用 Btrace 的一些方法和注意事项,希望能为你带来一些有价值的参考。

当然,在使用 Btrace 之前要先安装,具体方法请参考相关说明,就不在此赘述了。由于 Btrace 并非可视化的监控工具,采集结果是以文本信息的方式输出来的,故需要我们对结果进行必要的统计分析才能找出应用的热点方法。在实际使用中,笔者通常按照以下步骤进行热点方法的抓取:

① 编写采集脚本;

② 运行采集脚本;

③ 执行场景;

④ 停止场景;

⑤ 停止采集脚本;

⑥ 获取方法列表;

⑦ 分析结果,获得方法的平均耗时与执行次数。

下面具体介绍一下每一步的操作要点。

编写采集脚本

首先要编写一个脚本,用于定义要抓取的热点方法。脚本的大概结构如图 1 所示,下面对脚本做一个简单的介绍。

图1  监控脚本

首先导入 Btrace 自带的两个包,然后像正常编写 Java 类一样编写一个简单的类,类名的命名只要符合 Java 规范即可。

@OnMethod 注解里的内容是定义触发的条件,当程序执行时满足了注解内的条件就会执行下面的 test-trace(这个方法可以自由命名)方法。

变量 clazz 是要抓取方法的范围,即 class,这个变量指定的路径越详细抓取的方法就会越少,输出结果也越少,通常我们只抓取项目本身定义的类中的所有方法即可,调用的第三方及使用的框架的类可以过滤掉。

method 的作用是定义需要监控的方法,可以使用正则表达式的方式进行匹配。

location 变量的作用是定义方法的拦截位置,我们要获取方法的执行耗时需要使用 Kind.RETURN,这样在方法执行完成后我们就可以获取返执行时间 @Duration。

脚本中的 test-trace 方法是我们要输出的抓取结果的一些代码,当 @OnMethod 触发条件满足时就会被执行。

再看一下几个参数,

@ProbeClassName 是当前执行到的包含完整包路径的类名称;

@ProbeMethodName 是当前被执行到的方法名称;

@Duration 是当前方法执行消耗的时间,单位为纳秒,所以在输出这个耗时的时候,我们要把纳秒转化成毫秒,以增加可读性。

最后,我们只需使用一个 print 方法将这几个参数输出即可,输出的格式是类似于 “com.yeepay.*.* . queryList:100”。

整个脚本的结构非常简洁,很容易学习与掌握。当然 Btrace 不只提供这么简单的功能,如果你有更复杂的需求请参阅相关资料。这里需要说明的是,尽量对过滤的范围进行压缩,以排除其他无关类的影响。如果抓取的结果中没有热点方法,我们可以再尝试改变抓取的类的范围。

执行采集脚本

脚本编写完成之后,无需特别的编译即可执行了。如果在执行时报错,那么我们再回去修改脚本即可。执行前我们需要先获取被测应用的 PID,并且把抓取结果保存到文件中。命令格式如下:

btrace PID ./Test.java >> trace-res.txt

命令运行之后,如果没有报错,就说明 Btrace 已经开始工作了,只要程序相关的方法被执行到,并且符合采集的条件,那么采集结果就会输出到 trace-res.txt 文件中。

执行测试场景

采集脚本启动后就要进行测试场景的执行了。根据笔者的经验,建议发压的压力不要太大或者时间不要太长,否则收集的结果文件会很大,后续分析起来会比较费劲。发压一定时间后,采集的数据足够我们分析了,这时就要停止压力,然后把 Btrace 的进程 kill 掉。

获取应用的方法列表

有了采集结果,接下来我们就要对结果进行统计分析。首先,我们要获取方法列表,当然这一步在整个测试过程中只需进行一次,除非应用增加了新的方法或修改了某些方法的名称。方法列表是我们对采集结果进行分析的基础,后续我们要根据方法列表里的方法名称,进行逐个方法的采集结果的统计计算。下面这个命令是笔者对采集结果进行方法列表的提取操作:

cat trace-res.txt | awk -F ':' '{print $1}' | awk ‘!a[$0]++’ >> fuction-list.txt

执行完成后把 fuction-list.txt 文件中的方法列表拷贝到一个 Excel 表格中,作为分析的第一列。笔者 Excel 统计分析的格式如图 2 所示。

图2  热点方法采集结果分析表

输出采集结果

接下来还需要根据方法列表来获取每个方法的平均执行耗时与采集次数。同样,我们也使用 shell 命令来实现,具体的命令类似这样:

cat trace.txt | grep -a “com.yeepay.g3.utils.*” | awk -F ':' '{print $2}’ | awk ‘{sum+=$1} END {if (NR==0) print "0 0";else if (NR>0) print sum/NR,NR}’

这个命令的最后一个管道对输出结果进行了一次判断,避免变量 NR(行数)出现 0 的时导致命令报错。

一般情况下应用的方法会比较多,如果每次都手工写命令并执行那也是一件体力活。这时我们把这个命令统一写到一个脚本中,分析的时候执行脚本即可。笔者写好后的整体效果如图3所示,有密集恐惧症的读者请忽略此图。

图3 自动解析输出方法平均耗时与执行次数的 shell 脚本

执行完这个脚本后,输出的结果包含两列,第一列是“平均耗时”,第二列是“采集次数”,把这两列结果直接复制到 Excel 中,即可对结果进行分析。我们可以对“平均耗时”和“每笔交易执行次数”进行排序,以发现耗时最高和平均执行次数最高的方法。

笔者的分析结果如图 2 所示。其中“原子方法”列的状态是与开发沟通后确定的。所谓的原子方法是指这个方法是否还调用别的方法,如果没有调用别的方法,那么我们就认为是原子方法。如果一个方法是原子方法且平均耗时较长,那肯定就是热点方法,也是要重点进行优化的地方。

另外一列“每笔交易执行次数”需要大家注意,这一列的值是笔者在另外的一个场景中把响应时间阈值设置为0时获取的结果,并不是图 2 中“采集次数”直接除于请求次数所得的结果。

通过图 2 中的表可以清晰地找出当前的热点方法,然后研发人员就可以重点对这些方法进行优化。通过使用 Btrace 工具可以大大缩短定位热点方法的时间,快速而有效。笔者根据图 2 的结果,对应用进行优化,发现应用的同步处理能力可以提升 3 倍,异步处理能力可以提升 10 倍。

影响性分析

最后需要大家注意的是使用 Btrace 时会对应用产生影响。经笔者实践,如果监控阈值为 0(采集脚本中的 if 语句 if duration >= 0 ),对应用的影响是致命的,可能会造成 TPS 严重下降,因为会有大量的监控结果输出导致磁盘 IO 被打满。在笔者做的项目中实测 200 笔交易共输出 2.5GB 的采集信息,实在惊人!而采集阈值为 10 毫秒时,对应用的性能影响为 25% 左右。因此,采集的阈值越大,影响越小;过滤的方法越多对应用的影响越小。所以在使用 Btrace 时建议大家设置合理的阈值,减少输出量

另外,建议大家单独执行一个场景用于获取方法的列表及单笔交易执行次数,比如将阈值设置为 0,连续发起 10 笔请求,然后对结果进行分析,获取方法列表及单笔交易执行次数,这样的动作我们只进行一次就可以了。

好消息

易宝 CTO 陈斌翻译的新书《架构真经》正在京东和亚马逊热卖!

《架构真经》:《架构即未来》姊妹篇,硅谷大咖的干货呈现,互联网架构的50条军规。唐彬、向江旭、叶亚明、段念、吴华鹏、张瑞海、韩军、程炳皓、张云泉、余晨、李大学、霍泰稳联袂力荐。

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

推荐阅读更多精彩内容