简述

  • Arthas官网：https://arthas.aliyun.com/
  • Arthas（Alibaba Java Diagnostic Tool）是一个强大的Java诊断工具，它可以监控和分析运行中的Java应用程序。它采用了字节码注入的方式来实现监控和调试功能。

底层原理

  1. 字节码注入：Arthas使用字节码注入技术，通过修改目标Java程序的字节码来动态注入监控代码和收集性能信息，这种方式不需要对应用程序进行重新编译或者重启，因为重启之后问题可能不容易复现，因此可以在运行时对其进行诊断和分析。
  2. Instrumentation API：Arthas使用Java的Instrumentation API来实现字节码注入。这个API运行类加载器会在加载类时，对类的字节码进行修改，Arthas通过这个API来注入自己的监控代码，以便捕获方法执行、性能统计等信息。
  3. Agent方式：Arthas以Java Agent的形式运行，通过JVM的Agent机制加载到目标应用程序中。Java Agent是一种运行在Java程序之外的Java程序，可以在目标应用运行时被动态地附加到应用程序进程中，并与之交互。

基本使用

  • 由于执行Arthas程序的用户需要与目标进程具有相同的权限，目前公司的项目都是通过容器启动的，所以我们首先要进入Java服务容器的内部，然后下载Arthas的jar包，然后再启动（Windows环境下直接在CMD窗口运行即可） 
    1
    2
    curl -O https://arthas.aliyun.com/arthas-boot.jar
    java -jar arthas-boot.jar
  • 启动之后就会列出当前所有的Java进程，我们根据自身需求来选择要监控的Java进程 
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    root@ff3c3ed00ac8:/data# java -jar arthas-boot.jar 
        [INFO] JAVA_HOME: /usr/local/openjdk-8/jre
        [INFO] arthas-boot version: 3.7.1
        [INFO] Found existing java process, please choose one and input the serial number of the process, eg : 1. Then hit ENTER.
        * [1]: 7 /data/PaperReduction.jar
        # 找到一个Java进程，按下对应的数字键来进行监控
        1
        [INFO] arthas home: /root/.arthas/lib/3.7.1/arthas
        [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.7.1                                                                
        main_class                                                                      
        pid        7                                                                    
        time       2023-09-06 19:15:06        

    [arthas@7]$
  • 那么现在的需求是分析从Spring框架接收到HTTP请求，然后分派到对应的Controller方法之间的耗时，这里我们只需要使用Arthas的一个小功能trace，它可以动态地计算方法调用路径和耗时。
    1. trace方法内部调用路径，并输出方法路径上每个节点的耗时。
    2. trace命令能主动搜索class-pattern/method-pattern，对应的方法带哦用路径，渲染和统计整个调用链路上的所有性能开销和追踪调用链路。
  • 再了解两个小概念
    1. DispatcherServlet（org.springframework.web.servlet.DispatcherServlet）：DispatcherServlet 是Spring MVC的核心，它负责接收HTTP请求并将请求分派给相应的Controller。我们可以从DispatcherServlet的请求处理方法入手，分析请求的调用链和处理时间。
    2. HandlerMapping（org.springframework.web.servlet.HandlerMapping）：HandlerMapping 负责将请求映射到具体的Controller方法。您可以分析不同的HandlerMapping实现，以了解请求到Controller方法的映射过程。

  • 那我们现在执行 trace org.springframework.web.servlet.DispatcherServlet * 来分析一下调用链上都经过了什么

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    29
    30
    31
    32
    33
    34
    35
    36
    37
    38
    39
    40
    41
    42
    43
    44
    45
    46
    47
    48
    49
    50
    51
    52
    53
    `---ts=2023-09-07 10:27:40;thread_name=http-nio-80-exec-5;id=33;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@55634720
        `---[5.59488ms] org.springframework.web.servlet.DispatcherServlet:doService()
            +---[0.63% 0.035364ms ] org.springframework.web.servlet.DispatcherServlet:logRequest() #926
            |   `---[59.32% 0.020979ms ] org.springframework.web.servlet.DispatcherServlet:logRequest()
            |       `---[28.81% 0.006045ms ] org.springframework.core.log.LogFormatUtils:traceDebug() #980
            +---[0.12% 0.006831ms ] org.springframework.web.util.WebUtils:isIncludeRequest() #931
            +---[0.10% 0.005813ms ] org.springframework.web.servlet.DispatcherServlet:getWebApplicationContext() #943
            +---[0.07% 0.004058ms ] javax.servlet.http.HttpServletRequest:setAttribute() #943
            +---[0.06% 0.003624ms ] javax.servlet.http.HttpServletRequest:setAttribute() #944
            +---[0.06% 0.003435ms ] javax.servlet.http.HttpServletRequest:setAttribute() #945
            +---[0.61% 0.034354ms ] org.springframework.web.servlet.DispatcherServlet:getThemeSource() #946
            |   `---[61.47% 0.021117ms ] org.springframework.web.servlet.DispatcherServlet:getThemeSource()
            |       `---[46.43% min=0.0046ms,max=0.005205ms,total=0.009805ms,count=2] org.springframework.web.servlet.DispatcherServlet:getWebApplicationContext() #806
            +---[0.06% 0.003434ms ] javax.servlet.http.HttpServletRequest:setAttribute() #946
            +---[0.22% 0.012272ms ] org.springframework.web.servlet.FlashMapManager:retrieveAndUpdate() #949
            +---[0.16% 0.008744ms ] org.springframework.web.servlet.FlashMap:<init>() #953
            +---[0.12% 0.006509ms ] javax.servlet.http.HttpServletRequest:setAttribute() #953
            +---[0.09% 0.004867ms ] javax.servlet.http.HttpServletRequest:setAttribute() #954
            +---[0.07% 0.003641ms ] javax.servlet.http.HttpServletRequest:getAttribute() #959
            +---[2.51% 0.140331ms ] org.springframework.web.util.ServletRequestPathUtils:parseAndCache() #960
            +---[92.44% 5.172017ms ] org.springframework.web.servlet.DispatcherServlet:doDispatch() #964
            |   `---[99.30% 5.136033ms ] org.springframework.web.servlet.DispatcherServlet:doDispatch()
            |       +---[0.13% 0.006484ms ] org.springframework.web.context.request.async.WebAsyncUtils:getAsyncManager() #1036
            |       +---[0.72% 0.036845ms ] org.springframework.web.servlet.DispatcherServlet:checkMultipart() #1043
            |       |   `---[55.87% 0.020586ms ] org.springframework.web.servlet.DispatcherServlet:checkMultipart()
            |       |       `---[55.39% 0.011402ms ] org.springframework.web.multipart.MultipartResolver:isMultipart() #1197
            |       +---[5.09% 0.261359ms ] org.springframework.web.servlet.DispatcherServlet:getHandler() #1047
            |       |   `---[94.84% 0.247868ms ] org.springframework.web.servlet.DispatcherServlet:getHandler()
            |       |       `---[94.99% 0.235439ms ] org.springframework.web.servlet.HandlerMapping:getHandler() #1265
            |       +---[0.11% 0.005579ms ] org.springframework.web.servlet.HandlerExecutionChain:getHandler() #1054
            |       +---[0.62% 0.031705ms ] org.springframework.web.servlet.DispatcherServlet:getHandlerAdapter() #1054
            |       |   `---[56.86% 0.018028ms ] org.springframework.web.servlet.DispatcherServlet:getHandlerAdapter()
            |       |       `---[32.95% 0.005941ms ] org.springframework.web.servlet.HandlerAdapter:supports() #1301
            |       +---[0.06% 0.003195ms ] javax.servlet.http.HttpServletRequest:getMethod() #1057
            |       +---[0.11% 0.00577ms ] org.springframework.http.HttpMethod:matches() #1058
            |       +---[0.05% 0.00277ms ] org.springframework.http.HttpMethod:matches() #1059
            |       +---[40.64% 2.08729ms ] org.springframework.web.servlet.HandlerExecutionChain:applyPreHandle() #1066
            |       +---[0.08% 0.004206ms ] org.springframework.web.servlet.HandlerExecutionChain:getHandler() #1071
            |       +---[47.64% 2.44697ms ] org.springframework.web.servlet.HandlerAdapter:handle() #1071
            |       +---[0.11% 0.00578ms ] org.springframework.web.context.request.async.WebAsyncManager:isConcurrentHandlingStarted() #1073
            |       +---[0.77% 0.039313ms ] org.springframework.web.servlet.DispatcherServlet:applyDefaultViewName() #1077
            |       |   `---[34.47% 0.01355ms ] org.springframework.web.servlet.DispatcherServlet:applyDefaultViewName()
            |       +---[0.16% 0.008038ms ] org.springframework.web.servlet.HandlerExecutionChain:applyPostHandle() #1078
            |       +---[1.41% 0.072602ms ] org.springframework.web.servlet.DispatcherServlet:processDispatchResult() #1088
            |       |   `---[66.42% 0.04822ms ] org.springframework.web.servlet.DispatcherServlet:processDispatchResult()
            |       |       +---[6.78% 0.003268ms ] org.apache.commons.logging.Log:isTraceEnabled() #1155
            |       |       +---[10.20% 0.004917ms ] org.springframework.web.context.request.async.WebAsyncUtils:getAsyncManager() #1160
            |       |       +---[5.81% 0.0028ms ] org.springframework.web.context.request.async.WebAsyncManager:isConcurrentHandlingStarted() #1160
            |       |       `---[16.01% 0.007718ms ] org.springframework.web.servlet.HandlerExecutionChain:triggerAfterCompletion() #1167
            |       `---[0.11% 0.00572ms ] org.springframework.web.context.request.async.WebAsyncManager:isConcurrentHandlingStarted() #1098
            +---[0.09% 0.004919ms ] org.springframework.web.context.request.async.WebAsyncUtils:getAsyncManager() #967
            +---[0.05% 0.002756ms ] org.springframework.web.context.request.async.WebAsyncManager:isConcurrentHandlingStarted() #967
            `---[0.20% 0.011002ms ] org.springframework.web.util.ServletRequestPathUtils:setParsedRequestPath() #974
    1. doService() 方法：首先，请求进入 DispatcherServlet 的 doService() 方法。这是请求处理的入口点。在这个方法中，会进行以下一些重要的操作：
      1. logRequest() 方法：这个方法用于记录请求的信息，例如请求的HTTP方法、URI等。它通常用于调试和日志记录目的。
      2. isIncludeRequest() 方法：检查当前请求是否是包含（include）请求。包含请求是指一个Servlet可以包含另一个Servlet的响应内容。
      3. getWebApplicationContext() 方法：获取Spring的Web应用程序上下文，该上下文包含了Spring应用程序中的各种bean定义和配置。
      4. setAttribute() 方法：在 HttpServletRequest 对象中设置一些属性，以便后续的处理可以访问这些属性。这通常用于在请求处理过程中传递数据。
      5. getThemeSource() 方法：获取主题资源，主题通常用于定制应用程序的外观。
    2. doDispatch() 方法：在 doService() 中，DispatcherServlet 调用 doDispatch() 方法，这是实际的请求分发和处理的关键方法。在这个方法中，会进行以下操作：
      1. getAsyncManager() 方法：获取异步请求管理器，用于处理异步请求。
      2. checkMultipart() 方法：检查请求是否包含多部分（multipart）内容，通常用于文件上传。
      3. getHandler() 方法：获取用于处理请求的处理器（Handler）。这个方法是决定如何处理请求的关键点。
        • getHandlerMapping() 方法：获取用于查找处理器的Handler Mapping。Handler Mapping 根据请求的URL或其他条件，将请求映射到适当的处理器方法。
        • 一旦找到了合适的处理器，它会被返回，以便后续的请求处理。
    • 下面是我上传了一个文件，可以看到耗时绝大部分都是在checkMultipart()方法上，等下次上传文件异常缓慢的时候，可以结合Nginx日志中的响应耗时和这里的耗时来分析到底是哪个步骤慢
      1
      2
      3
      4
      5
      6
      7
      8
      9
      10
      11
      12
      13
      14
      15
      16
      17
      18
      19
      20
      21
      22
      23
      24
      25
      26
      27
      28
      29
      30
      31
      32
      33
      34
      35
      36
      37
      38
      39
      40
      41
      42
      43
      44
      45
      46
      47
      48
      49
      50
      51
      52
      53
      54
      55
      56
      57
      58
      59
      60
      61
      62
      `---ts=2023-09-07 11:00:24;thread_name=http-nio-80-exec-7;id=35;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@55634720
          `---[725.449628ms] org.springframework.web.servlet.DispatcherServlet:doService()
              +---[0.17% 1.209254ms ] org.springframework.web.servlet.DispatcherServlet:logRequest() #926
              |   `---[97.75% 1.182007ms ] org.springframework.web.servlet.DispatcherServlet:logRequest()
              |       `---[6.82% 0.080573ms ] org.springframework.core.log.LogFormatUtils:traceDebug() #980
              +---[0.00% 0.014693ms ] org.springframework.web.util.WebUtils:isIncludeRequest() #931
              +---[0.00% 0.012721ms ] org.springframework.web.servlet.DispatcherServlet:getWebApplicationContext() #943
              +---[0.00% 0.016321ms ] javax.servlet.http.HttpServletRequest:setAttribute() #943
              +---[0.00% 0.003773ms ] javax.servlet.http.HttpServletRequest:setAttribute() #944
              +---[0.00% 0.005059ms ] javax.servlet.http.HttpServletRequest:setAttribute() #945
              +---[0.01% 0.06607ms ] org.springframework.web.servlet.DispatcherServlet:getThemeSource() #946
              |   `---[62.24% 0.041121ms ] org.springframework.web.servlet.DispatcherServlet:getThemeSource()
              |       `---[28.35% min=0.004431ms,max=0.007225ms,total=0.011656ms,count=2] org.springframework.web.servlet.DispatcherServlet:getWebApplicationContext() #806
              +---[0.00% 0.005496ms ] javax.servlet.http.HttpServletRequest:setAttribute() #946
              +---[0.00% 0.021549ms ] org.springframework.web.servlet.FlashMapManager:retrieveAndUpdate() #949
              +---[0.00% 0.018169ms ] org.springframework.web.servlet.FlashMap:<init>() #953
              +---[0.00% 0.004453ms ] javax.servlet.http.HttpServletRequest:setAttribute() #953
              +---[0.00% 0.007301ms ] javax.servlet.http.HttpServletRequest:setAttribute() #954
              +---[0.00% 0.010647ms ] javax.servlet.http.HttpServletRequest:getAttribute() #959
              +---[0.09% 0.633634ms ] org.springframework.web.util.ServletRequestPathUtils:parseAndCache() #960
              +---[99.66% 722.964056ms ] org.springframework.web.servlet.DispatcherServlet:doDispatch() #964
              |   `---[100.00% 722.939122ms ] org.springframework.web.servlet.DispatcherServlet:doDispatch()
              |       +---[0.00% 0.011085ms ] org.springframework.web.context.request.async.WebAsyncUtils:getAsyncManager() #1036
              |       +---[4.74% 34.255344ms ] org.springframework.web.servlet.DispatcherServlet:checkMultipart() #1043
              |       |   `---[99.94% 34.235142ms ] org.springframework.web.servlet.DispatcherServlet:checkMultipart()
              |       |       +---[0.05% 0.017859ms ] org.springframework.web.multipart.MultipartResolver:isMultipart() #1197
              |       |       +---[0.03% 0.010256ms ] org.springframework.web.util.WebUtils:getNativeRequest() #1198
              |       |       +---[0.13% 0.046108ms ] org.springframework.web.servlet.DispatcherServlet:hasMultipartException() #1203
              |       |       |   `---[65.16% 0.030045ms ] org.springframework.web.servlet.DispatcherServlet:hasMultipartException()
              |       |       |       `---[18.36% 0.005515ms ] javax.servlet.http.HttpServletRequest:getAttribute() #1230
              |       |       `---[99.65% 34.116944ms ] org.springframework.web.multipart.MultipartResolver:resolveMultipart() #1209
              |       +---[0.12% 0.836273ms ] org.springframework.web.servlet.DispatcherServlet:getHandler() #1047
              |       |   `---[96.10% 0.803643ms ] org.springframework.web.servlet.DispatcherServlet:getHandler()
              |       |       `---[88.91% 0.714557ms ] org.springframework.web.servlet.HandlerMapping:getHandler() #1265
              |       +---[0.00% 0.011929ms ] org.springframework.web.servlet.HandlerExecutionChain:getHandler() #1054
              |       +---[0.01% 0.05063ms ] org.springframework.web.servlet.DispatcherServlet:getHandlerAdapter() #1054
              |       |   `---[63.99% 0.032397ms ] org.springframework.web.servlet.DispatcherServlet:getHandlerAdapter()
              |       |       `---[37.22% 0.012058ms ] org.springframework.web.servlet.HandlerAdapter:supports() #1301
              |       +---[0.00% 0.008964ms ] javax.servlet.http.HttpServletRequest:getMethod() #1057
              |       +---[0.00% 0.017054ms ] org.springframework.http.HttpMethod:matches() #1058
              |       +---[0.00% 0.003344ms ] org.springframework.http.HttpMethod:matches() #1059
              |       +---[0.63% 4.578389ms ] org.springframework.web.servlet.HandlerExecutionChain:applyPreHandle() #1066
              |       +---[0.00% 0.005151ms ] org.springframework.web.servlet.HandlerExecutionChain:getHandler() #1071
              |       +---[94.22% 681.164697ms ] org.springframework.web.servlet.HandlerAdapter:handle() #1071
              |       +---[0.00% 0.022867ms ] org.springframework.web.context.request.async.WebAsyncManager:isConcurrentHandlingStarted() #1073
              |       +---[0.01% 0.046345ms ] org.springframework.web.servlet.DispatcherServlet:applyDefaultViewName() #1077
              |       |   `---[19.75% 0.009155ms ] org.springframework.web.servlet.DispatcherServlet:applyDefaultViewName()
              |       +---[0.00% 0.023564ms ] org.springframework.web.servlet.HandlerExecutionChain:applyPostHandle() #1078
              |       +---[0.02% 0.122935ms ] org.springframework.web.servlet.DispatcherServlet:processDispatchResult() #1088
              |       |   `---[76.98% 0.09464ms ] org.springframework.web.servlet.DispatcherServlet:processDispatchResult()
              |       |       +---[24.65% 0.023328ms ] org.apache.commons.logging.Log:isTraceEnabled() #1155
              |       |       +---[16.65% 0.015762ms ] org.springframework.web.context.request.async.WebAsyncUtils:getAsyncManager() #1160
              |       |       +---[6.36% 0.006018ms ] org.springframework.web.context.request.async.WebAsyncManager:isConcurrentHandlingStarted() #1160
              |       |       `---[14.57% 0.013792ms ] org.springframework.web.servlet.HandlerExecutionChain:triggerAfterCompletion() #1167
              |       +---[0.00% 0.004283ms ] org.springframework.web.context.request.async.WebAsyncManager:isConcurrentHandlingStarted() #1098
              |       `---[0.23% 1.628707ms ] org.springframework.web.servlet.DispatcherServlet:cleanupMultipart() #1107
              |           `---[98.68% 1.607223ms ] org.springframework.web.servlet.DispatcherServlet:cleanupMultipart()
              |               +---[0.50% 0.008005ms ] org.springframework.web.util.WebUtils:getNativeRequest() #1248
              |               `---[97.93% 1.574022ms ] org.springframework.web.multipart.MultipartResolver:cleanupMultipart() #1250
              +---[0.00% 0.009553ms ] org.springframework.web.context.request.async.WebAsyncUtils:getAsyncManager() #967
              +---[0.00% 0.006599ms ] org.springframework.web.context.request.async.WebAsyncManager:isConcurrentHandlingStarted() #967
              `---[0.01% 0.10787ms ] org.springframework.web.util.ServletRequestPathUtils:setParsedRequestPath() #974
    • 分析特定方法的耗时，我们只需要明确指定一下类的全限定名以及方法名即可，例如 trace com.aimc.paperreduction.web.controller.CommonController uploadPaper，这里是分析CommonController包下的uploadPaper方法，正好之前加了阿里云的文本检测，可以看一下对性能的影响
      1
      2
      3
      4
      5
      6
      7
      8
      9
      10
      11
      12
      13
      14
      15
      16
      17
      18
      19
      20
      21
      22
      23
      24
      25
      26
      27
      28
      29
      30
      31
      32
      33
      34
      [arthas@7]$ trace com.aimc.paperreduction.web.controller.CommonController uploadPaper
      Press Q or Ctrl+C to abort.
      Affect(class count: 2 , method count: 2) cost in 292 ms, listenerId: 20
      `---ts=2023-09-07 11:45:12;thread_name=http-nio-80-exec-5;id=33;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@55634720
          `---[931.752981ms] com.aimc.paperreduction.web.controller.CommonController$$EnhancerBySpringCGLIB$$864d4ba2:uploadPaper()
              `---[99.94% 931.15232ms ] org.springframework.cglib.proxy.MethodInterceptor:intercept()
                  `---[97.68% 909.537879ms ] com.aimc.paperreduction.web.controller.CommonController:uploadPaper()
                      +---[0.02% 0.160456ms ] org.slf4j.Logger:info() #221
                      +---[0.00% 0.043686ms ] org.springframework.web.multipart.MultipartFile:isEmpty() #224
                      +---[99.91% 908.687093ms ] com.aimc.paperreduction.service.OrderService:uploadPaper() #227
                      +---[0.00% 0.021838ms ] com.aimc.paperreduction.common.wrapper.Wrapper:getCode() #228
                      +---[0.04% 0.325031ms ] org.slf4j.Logger:info() #232
                      +---[0.00% 0.017715ms ] com.aimc.paperreduction.common.wrapper.Wrapper:getResult() #233
                      `---[0.00% 0.028309ms ] com.aimc.paperreduction.web.controller.CommonController:success() #233

      [arthas@7]$ trace  com.aimc.paperreduction.service.OrderService uploadPaper
      Press Q or Ctrl+C to abort.
      Affect(class count: 4 , method count: 3) cost in 659 ms, listenerId: 21
      `---ts=2023-09-07 11:46:32;thread_name=http-nio-80-exec-9;id=37;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@55634720
          `---[871.142915ms] com.aimc.paperreduction.service.impl.OrderServiceImpl$$EnhancerBySpringCGLIB$$a91e94c:uploadPaper()
              `---[99.98% 871.000878ms ] org.springframework.cglib.proxy.MethodInterceptor:intercept()
                  `---[99.99% 870.908438ms ] com.aimc.paperreduction.service.impl.OrderServiceImpl:uploadPaper()
                      +---[0.01% 0.049453ms ] com.aimc.paperreduction.common.wrapper.Wrapper:<init>() #1243
                      +---[0.00% 0.010567ms ] org.springframework.web.multipart.MultipartFile:getOriginalFilename() #1246
                      +---[0.01% 0.064652ms ] com.aimc.paperreduction.utils.StringUtil:extractPathExt() #1246
                      +---[0.01% 0.099063ms ] com.aimc.paperreduction.utils.PathUtil:getRealDiskPath() #1263
                      +---[0.81% 7.026517ms ] com.aimc.paperreduction.service.impl.OrderServiceImpl:transferToDisk() #1264
                      +---[6.17% 53.694128ms ] com.aspose.words.Document:<init>() #1272
                      +---[41.01% 357.150979ms ] com.aspose.words.Document:save() #1274
                      +---[0.22% 1.918176ms ] com.aspose.words.Document:cleanup() #1277
                      +---[0.00% 0.010126ms ] com.aimc.paperreduction.model.entity.PaperInfo:<init>() #1284
                      +---[14.27% 124.293242ms ] com.aimc.paperreduction.utils.CommonUtil:countWords() #1286
                      +---[34.64% 301.714162ms ] com.aimc.paperreduction.utils.CommonUtil:isGreenDoc() #1287
                      +---[0.01% 0.05563ms ] org.apache.commons.lang3.StringUtils:isNotBlank() #1288
    • 从上面的结果中，我们看到，阿里的文本检测占了三分之一的时长，我们可以继续使用trace命令来看为什么耗时这么久
      1
      2
      3
      4
      5
      6
      7
      8
      9
      Affect(class count: 1 , method count: 1) cost in 233 ms, listenerId: 22
      `---ts=2023-09-07 11:49:51;thread_name=http-nio-80-exec-10;id=38;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@55634720
          `---[294.261119ms] com.aimc.paperreduction.utils.CommonUtil:isGreenDoc()
              +---[25.88% 76.155345ms ] org.apache.poi.xwpf.usermodel.XWPFDocument:<init>() #1700
              +---[0.00% 0.006894ms ] org.apache.poi.xwpf.usermodel.XWPFDocument:getParagraphs() #1701
              +---[0.44% min=0.001325ms,max=0.124972ms,total=1.306473ms,count=39] org.apache.poi.xwpf.usermodel.XWPFParagraph:getText() #1702
              +---[73.52% 216.339053ms ] com.aimc.paperreduction.utils.TextReview:textReview() #1709
              +---[0.00% 0.012255ms ] com.aimc.paperreduction.utils.TextReview:textReview() #1715
              `---[0.02% 0.048882ms ] org.apache.poi.xwpf.usermodel.XWPFDocument:close() #1717
    • 可以看到主要是TextReview耗时较长，同时XWPFDocument对象的创建也很吃性能，代码中要避免频繁创建销毁此对象，继续看TextReview
      1
      2
      3
      4
      5
      6
      7
      8
      9
      10
      11
      12
      13
      14
      15
      16
      17
      18
      19
      20
      21
      22
      23
      24
      [arthas@7]$ trace com.aimc.paperreduction.utils.TextReview textReview
      Press Q or Ctrl+C to abort.
      Affect(class count: 1 , method count: 1) cost in 202 ms, listenerId: 23
      `---ts=2023-09-07 11:53:18;thread_name=http-nio-80-exec-1;id=2f;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@55634720
          `---[209.523489ms] com.aimc.paperreduction.utils.TextReview:textReview()
              +---[0.03% 0.0623ms ] org.apache.commons.lang3.StringUtils:isBlank() #17
              +---[0.01% 0.01229ms ] com.aliyun.teaopenapi.models.Config:<init>() #21
              +---[0.01% 0.011889ms ] com.aliyun.teaopenapi.models.Config:setAccessKeyId() #22
              +---[0.00% 0.007757ms ] com.aliyun.teaopenapi.models.Config:setAccessKeySecret() #23
              +---[0.00% 0.007802ms ] com.aliyun.teaopenapi.models.Config:setEndpoint() #25
              +---[0.00% 0.006391ms ] com.aliyun.teaopenapi.models.Config:setConnectTimeout() #26
              +---[0.00% 0.006966ms ] com.aliyun.teaopenapi.models.Config:setReadTimeout() #27
              +---[0.07% 0.154858ms ] com.aliyun.green20220302.Client:<init>() #28
              +---[0.01% 0.011248ms ] com.alibaba.fastjson.JSONObject:<init>() #30
              +---[0.01% 0.012672ms ] com.alibaba.fastjson.JSONObject:put() #31
              +---[0.01% 0.01861ms ] com.aliyun.green20220302.models.TextModerationRequest:<init>() #33
              +---[0.01% 0.012414ms ] com.aliyun.green20220302.models.TextModerationRequest:setService() #34
              +---[0.08% 0.160351ms ] com.alibaba.fastjson.JSONObject:toJSONString() #35
              +---[0.00% 0.009442ms ] com.aliyun.green20220302.models.TextModerationRequest:setServiceParameters() #35
              +---[99.33% 208.114925ms ] com.aliyun.green20220302.Client:textModeration() #36
              +---[0.01% 0.028103ms ] com.aliyun.green20220302.models.TextModerationResponse:getBody() #37
              +---[0.01% 0.013397ms ] com.aliyun.green20220302.models.TextModerationResponseBody:getCode() #38
              +---[0.01% 0.018539ms ] com.aliyun.green20220302.models.TextModerationResponseBody:getData() #40
              `---[0.02% 0.031569ms ] com.aliyun.green20220302.models.TextModerationResponseBody$TextModerationResponseBodyData:getLabels() #41
    • 定位到代码中
      1
      TextModerationResponse response = client.textModeration(textModerationRequest);
    • 这是一个同步调用，会等待服务器返回结果，等待期间会阻塞，如果服务端处理时间较长，这个代码会导致程序在这里一直阻塞。优化方案就是把这里改成了异步处理
    • 其实解决很简单，关键在于怎么定位并找到解决问题的方法，特意写了篇文章来记录一下