性能分析-java程序篇之案例-工具和方法

1. 背景说明

线上服务响应时间超过40秒，登陆服务器发现cpu将近100%了(以下图)，针对此问题，本文说明排查过程、工具以定位具体的缘由。

2. 分析排查过程

此类问题的排查，有两款神器可用，分别是async-profiler和arthas，async-profiler主要用于全局分析，经过此工具能够找到热点方法，
再用arthas对此热点方法进行详细的追踪，trace命令能够追踪方法的具体耗时，watch命令能够查看方法的出入参数，在结合源代码能够比较
方便定位到问题缘由。下面记录排查过程：

2.1. 用async-profiler生成火焰图

到下载后，解压后以下所示：

执行命令生成火焰图：
./profiler.sh -d 300 1485 -f ./test.svg
其中 -d 300 表示采集300s的数据，300s结束后，自动生成test.svg文件到当前目录。

2.2. 火焰图分析

用浏览器打开上面生成的svg文件，以下：

火焰图中纵向表明调用栈，即方法的调用深度，横向是方法占用cpu的时间比率，所以火焰图中若是出现平顶现象，说明相关方法耗时长（即为热点方法），是分析优化的对象；
从上图可看出：java/util/ComparableTimSort.countRunAndMakeAscending方法为热点方法，能够根据此方法的调用栈对相关方法进行追踪：
io/micrometer/core/instrument/MeterRegistry.getMappedId
io/micrometer/core/instrument/Tags.and

2.3. 追踪方法具体耗时和调用关系

此时可采用arthas工具，改工具的安装和使用方法可参考：《arthas用户指南》

2.3.1. 追踪getMappedId

arthas控制台中执行下面命令：
trace io.micromete/core.instrument.MeterRegistry getMappedId

io.micrometer.core.instrument.MeterRegistry#getMappedId耗时近40s，期间此方法中调用了2458次MeterFilter.map()方法: 该方法源代码以下：

经过屡次执行该命令发现，filters数组会随着请求增长而不断上涨；那么这个filters数组究竟是什么内容呢？

2.3.2. 监控类的返回对象

watch MeterRegistry "{returnObj}" -x 3 -n 3

发现数组中储存的都是相同内容的tag，继续查看源代码，io.micrometer.core.instrument.MeterRegistry类中成员变量赋值的相关代码：

2.3.3. 监控Tags and方法的入参

watch io.micrometer.core.instrument.Tags and "{params}" -x 2 -b -n 4

2.4. 缘由

commonTags每调用一次，filters数组长度+1，会进行一次copy，不断增加，getMappedId方法中循环对tag进行and操做、排序、去重致使cpu飙高；
下面是致使这个问题缘由精简后的模拟代码：

2.5. 解决方式

commonTags应在服务初始化的时候设置，如在spring boot的配置文件中设置：