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


    1. 背景说明

      线上服务响应时间超过40秒,登录服务器发现cpu将近100%了(如下图),针对此问题,本文说明排查过程、工具以定位具体的原因。
    
    cpu使用率 # 2. 分析排查过程 此类问题的排查,有两款神器可用,分别是async-profiler和arthas,async-profiler主要用于全局分析,通过此工具可以找到热点方法, 再用arthas对此热点方法进行详细的追踪,trace命令可以追踪方法的具体耗时,watch命令可以查看方法的出入参数,在结合源代码可以比较 方便定位到问题原因。下面记录排查过程: ## 2.1. 用async-profiler生成火焰图 到下载后,解压后如下所示: async-profiler安装目录 执行命令生成火焰图: ./profiler.sh -d 300 1485 -f ./test.svg 其中 -d 300 表示采集300s的数据,300s结束后,自动生成test.svg文件到当前目录。

    2.2. 火焰图分析

    用浏览器打开上面生成的svg文件,如下:
    async-profiler安装目录
    火焰图中纵向代表调用栈,即方法的调用深度,横向是方法占用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
    cpu使用率
    io.micrometer.core.instrument.MeterRegistry#getMappedId耗时近40s,期间此方法中调用了2458次MeterFilter.map()方法: 该方法源代码如下:
    async-profiler安装目录
    通过多次执行该命令发现,filters数组会随着请求增加而不断上涨;那么这个filters数组到底是什么内容呢?

    2.3.2. 监控类的返回对象

    watch *MeterRegistry * "{returnObj}" -x 3 -n 3
    MeterRegistry返回值
    发现数组中储存的都是相同内容的tag,继续查看源代码,io.micrometer.core.instrument.MeterRegistry类中成员变量赋值的相关代码:
    MeterRegistry返回值

    2.3.3. 监控Tags and方法的入参

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

    2.4. 原因

    commonTags每调用一次,filters数组长度+1,会进行一次copy,不断增长,getMappedId方法中循环对tag进行and操作、排序、去重导致cpu飙高;
    下面是导致这个问题原因精简后的模拟代码:
    and方法入参

    2.5. 解决方式

    commonTags应在服务初始化的时候设置,如在spring boot的配置文件中设置:
    and方法入参

  • 相关阅读:
    使用RF(robotframework)要安装哪些库
    MYSQL题目练习专用
    MySQL字段拼接
    WPF样式
    WPF数据模板
    WPF控件模板
    WPF布局
    面向对象程序设计原则
    设计模式之策略模式
    设计模式之简单工厂模式
  • 原文地址:https://www.cnblogs.com/bingjava/p/12064706.html
Copyright © 2020-2023  润新知