Arthas排查SpringBoot的耗时

简述

• 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窗口运行即可）

  curl -O https://arthas.aliyun.com/arthas-boot.jar
  java -jar arthas-boot.jar

• 启动之后就会列出当前所有的Java进程，我们根据自身需求来选择要监控的Java进程

  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 * 来分析一下调用链上都经过了什么

  `---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日志中的响应耗时和这里的耗时来分析到底是哪个步骤慢

  `---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方法，正好之前加了阿里云的文本检测，可以看一下对性能的影响

  [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命令来看为什么耗时这么久

  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

  [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

  • 定位到代码中

  TextModerationResponse response = client.textModeration(textModerationRequest);

  • 这是一个同步调用，会等待服务器返回结果，等待期间会阻塞，如果服务端处理时间较长，这个代码会导致程序在这里一直阻塞。优化方案就是把这里改成了异步处理
  • 其实解决很简单，关键在于怎么定位并找到解决问题的方法，特意写了篇文章来记录一下