使用Arthas排查性能问题

最新推荐文章于 2024-05-23 16:58:36 发布

=PNZ=BeijingL

最新推荐文章于 2024-05-23 16:58:36 发布

阅读量2.4k

点赞数 41

分类专栏： Java 文章标签： java 性能优化

本文为CSDN博主「=PNZ=BeijingL」的原创文章，遵循 CC-BY-NC-SA 版权协议，转载请附上原文出处链接及本声明。CC-BY-NC-SA协议为创作共用-署名-非商业性-相同方式共享

本文链接：https://blog.csdn.net/Beijing_L/article/details/134653032

版权

Java 专栏收录该内容

47 篇文章 0 订阅

订阅专栏

Arthas 是一款线上监控诊断产品，通过全局视角实时查看应用 load、内存、gc、线程的状态信息，并能在不修改应用代码的情况下，对业务问题进行诊断，包括查看方法调用的出入参、异常，监测方法执行耗时，类加载信息等，大大提升线上问题排查效率

1.问题背景

今天一到公司开发人员就因线上的性能问题寻求帮助，售后反馈系统升级后物理产品更换业务处理十分缓慢，有时卡主10几秒。

我先尝试从开发环境复现问题，发现开发环境处理并不慢。考虑到线上环境存在性能问题而开发环境没有这个问题，一般情况下是两边数据量差引起的。我们的开发环境中的数据比现场环境低几个数量级。可能某些SQL在线上执行比较慢引发了问题。我尝试打印慢SQL，发现日志中没有执行比较慢的SQL以及可疑日志。这个问题变得十分棘手。

2.问题分析

在毫无头绪时，只能借助一些工具来协助分析。本问题主要用到了Arthas 的trace命令

trace ：获取方法内部调用路径，并输出方法路径上的每个节点上耗时

参考： trace | arthas

排查过程

1.运行arthas ，并选择进程20408,20408是系统客户端使用的进程

D:\staibossCliente\arthas-bin>
D:\staibossCliente\arthas-bin>java -jar arthas-boot.jar
[INFO] arthas-boot version: 3.5.4
[INFO] Process 20408 already using port 3658
[INFO] Process 20408 already using port 8563
[INFO] Found existing java process, please choose one and input the serial number of the process, eg : 1. Then hit ENTER.
* [1]: 20408 D:\staibossCliente\staribossclient\stariboss-new-client.exe
1
[INFO] arthas home: D:\staibossCliente\arthas-bin
[INFO] The target process already listen port 3658, skip attach.
[INFO] arthas-client connect 127.0.0.1 3658
  ,---.  ,------. ,--------.,--.  ,--.  ,---.   ,---.
 /  O  \ |  .--. ''--.  .--'|  '--'  | /  O  \ '   .-'
|  .-.  ||  '--'.'   |  |   |  .--.  ||  .-.  |`.  `-.
|  | |  ||  |\  \    |  |   |  |  |  ||  | |  |.-'    |
`--' `--'`--' '--'   `--'   `--'  `--'`--' `--'`-----'
 
 
wiki       https://arthas.aliyun.com/doc
tutorials  https://arthas.aliyun.com/doc/arthas-tutorials.html
version    3.5.4
main_class
pid        20408
time       2023-11-20 17:38:39

2. 根据业务行为查看方法内部的处理时间

[arthas@20408]$ trace -E com.star.sms.richclient.accept.view.accept.acceptEditor2.ExchangePhysicalProductEditor initOptionalPhysicalProducts
Affect(class count: 1 , method count: 0) cost in 61 ms, listenerId: 10
No class or method is affected, try:
1. Execute `sm CLASS_NAME METHOD_NAME` to make sure the method you are tracing actually exists (it might be in your parent class).
2. Execute `options unsafe true`, if you want to enhance the classes under the `java.*` package.
3. Execute `reset CLASS_NAME` and try again, your method body might be too large.
4. Check arthas log: C:\Users\95225/logs/arthas/arthas.log
5. Visit https://github.com/alibaba/arthas/issues/47 for more details.
[arthas@20408]$
[arthas@20408]$
[arthas@20408]$
[arthas@20408]$ trace -E com.star.sms.richclient.accept.view.accept.acceptEditor2.ExchangePhysicalProductEditor subscriberChanged
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 3) cost in 152 ms, listenerId: 12
`---ts=2023-11-20 17:57:00;thread_name=AWT-EventQueue-0;id=f;is_daemon=false;priority=6;TCCL=com.star.sms.launch.LaunchURLClassLoader@17a8a02
    `---[12855.2434ms] com.star.sms.richclient.accept.view.accept.acceptEditor2.ExchangePhysicalProductEditor:subscriberChanged()
        +---[0.0065ms] org.apache.commons.logging.Log:debug() #115
        +---[0.0061ms] com.star.sms.richclient.accept.view.accept.acceptEditor2.ExchangePhysicalProductEditor:getSelectedSubscriber() #116
        +---[0.0033ms] com.star.sms.richclient.accept.view.accept2.page.displayer.ExchangePhyProductDisplayer:setSubscriber() #117
        +---[min=0.0032ms,max=0.0032ms,total=0.0064ms,count=2] com.star.sms.richclient.accept.view.accept.acceptEditor2.ExchangePhysicalProductEditor:getCurrentAction() #122
        +---[0.0031ms] com.star.sms.richclient.accept.view.accept.acceptEditor2.ExchangePhysicalProductEditor:getCurrentCustomer() #122
        +---[5947.6627ms] com.star.sms.richclient.accept.view.accept.acceptEditor2.ExchangePhysicalProductEditor:getPhyProducts() #122    // getPhyProducts消耗了6S
        +---[6907.4171ms] com.star.sms.richclient.accept.view.accept2.page.displayer.ExchangePhyProductDisplayer:onSubscriberChanged() #122  // getPhyProducts消耗了7S
        +---[0.0056ms] com.star.sms.richclient.accept.view.accept.acceptEditor2.ExchangePhysicalProductEditor:getCurrentCustomer() #126
        `---[0.0048ms] com.star.sms.richclient.accept.view.accept2.page.displayer.ExchangePhyProductDisplayer:setCurrentCustomer() #126

3.分析日志

从日志中可见， getPhyProducts 消耗了6秒， onSubscriberChanged消耗了7S。定位2个性能慢的方法后，进一步分析

[arthas@20408]$ trace -E com.star.sms.richclient.accept.view.accept2.page.displayer.ExchangePhyProductDisplayer onSubscriberChanged|getExchangableInfos|initOptionalPhysicalProducts
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 3) cost in 132 ms, listenerId: 14
`---ts=2023-11-20 17:59:13;thread_name=AWT-EventQueue-0;id=f;is_daemon=false;priority=6;TCCL=com.star.sms.launch.LaunchURLClassLoader@17a8a02
    `---[0.4848ms] com.star.sms.richclient.accept.view.accept2.page.displayer.ExchangePhyProductDisplayer:onSubscriberChanged()
        `---[0.1634ms] com.star.sms.richclient.accept.view.accept2.page.displayer.ExchangePhyProductDisplayer:clearTable() #195
 
`---ts=2023-11-20 17:59:19;thread_name=AWT-EventQueue-0;id=f;is_daemon=false;priority=6;TCCL=com.star.sms.launch.LaunchURLClassLoader@17a8a02
    `---[6979.1925ms] com.star.sms.richclient.accept.view.accept2.page.displayer.ExchangePhyProductDisplayer:onSubscriberChanged()
        +---[342.3417ms] com.star.sms.richclient.accept.view.accept2.page.displayer.ExchangePhyProductDisplayer:getExchangableInfos() #198
com.star.sms.model.order.dto.ExchangeInfo:setReturnResourceState() #1082
        +---[93.7515ms] com.star.sms.richclient.accept.view.accept2.page.displayer.ExchangePhyProductDisplayer:setTableDatas() #198
        `---[6543.0383ms] com.star.sms.richclient.accept.view.accept2.page.displayer.ExchangePhyProductDisplayer:initOptionalPhysicalProducts() #200
            `---[6542.9974ms] com.star.sms.richclient.accept.view.accept2.page.displayer.ExchangePhyProductDisplayer:initOptionalPhysicalProducts()    //initOptionalPhysicalProducts 消耗时间7S
                +---[0.0147ms] org.apache.commons.logging.Log:debug() #907
                +---[min=0.0015ms,max=0.0175ms,total=0.7956ms,count=202] com.star.sms.model.product.core.catalog.PhysicalProduct:getResourceDirectory() #911
                +---[min=0.0017ms,max=0.0306ms,total=0.6809ms,count=202] com.star.sms.model.product.other.ResourceDirectory:getId() #911
                +---[min=29.9191ms,max=55.5523ms,total=6528.053ms,count=202] com.star.sms.outerInterface.resource.service.IResourceExService:getResCatalogById() #911
                +---[min=0.0017ms,max=0.0447ms,total=1.0478ms,count=202] com.star.sms.model.resource.core.resparam.ResourceCatalog:getResourceType() #913
                +---[min=0.0034ms,max=0.0327ms,total=1.4611ms,count=202] com.star.sms.richclient.accept.view.accept2.page.displayer.ExchangePhyProductDisplayer:setPhysicalProductResourceType() #914
                +---[min=0.0023ms,max=0.0376ms,total=0.9837ms,count=202] org.apache.commons.logging.Log:isDebugEnabled() #929
                `---[0.0128ms] org.apache.commons.logging.Log:debug() #934

继续查看执行时间，发现程序中initOptionalPhysicalProducts 方法用时最长，是一个程序瓶颈，此方法中使用了循环，循环中IResourceExService:getResCatalogById方法调用了202次。

查看程序代码，这是一个典型的N+1此查询性能问题。循环中调用了N此业务查询获取ResourceCatalog信息。

  private void initOptionalPhysicalProducts() {
        logger.debug("<== Begin to initialize the optional physical product... ==>");

        for (PhysicalProduct physicalProduct : physicalProducts) {
            ResourceCatalog resourceCatalog = resourceExService.getResCatalogById(physicalProduct .getResourceDirectory().getId());   // 这里存在N+1次查询， 其中N=202
           
            //省略代码 dosomething

            if (logger.isDebugEnabled()) {
                logger.debug("<-- Get a product，name is：" + physicalProduct.getName()
                        + "； and its resource type Id is ：" + resourceType.getId() + " -->");
            }
        }
        logger.debug("<~~The end of the physical product to initialize the optional~~>");
    }

3.解决方法

对于N+1此查询可以通过id集合查询+分组方式来处理，修改后的代码

    private void initOptionalPhysicalProducts() {
        logger.debug("<== Begin to initialize the optional physical product... ==>");
        
        //1.获取ID集合
		List<Long> catalogids = new ArrayList<Long>();
		for (PhysicalProduct physicalProduct : physicalProducts) {
			catalogids.add(physicalProduct.getResourceDirectory().getId());
		}

        //2.只查询1次
		List<ResourceCatalog> catalogs = resourceExService.getResCatalogByIds(catalogids);
        
        //3.分组
		Map<Long, ResourceCatalog> map = new HashMap<Long, ResourceCatalog>();
		for (ResourceCatalog resourceCatalog : catalogs) {
			map.put(resourceCatalog.getId(), resourceCatalog);
		}
        
        for (PhysicalProduct physicalProduct : physicalProducts) {
            ResourceCatalog resourceCatalog = map.get(physicalProduct.getResourceDirectory().getId()); //内存里获取
           
            //省略代码 dosomething
            
            if (logger.isDebugEnabled()) {
                logger.debug("<-- Get a product，name is：" + physicalProduct.getName()
                        + "； and its resource type Id is ：" + resourceType.getId() + " -->");
            }
        }
        logger.debug("<~~The end of the physical product to initialize the optional~~>");
    }

按照此处理方式，优化处理getPhyProducts 后问题解决，修正后业务处理时间在1秒内