Arthas troubleshoots SpringBoot time consumption

Brief description

• Arthas official website: https://arthas.aliyun.com/
• Arthas (Alibaba Java Diagnostic Tool) is a powerful Java diagnostic tool that can monitor and analyze running Java applications. It uses bytecode injection to implement monitoring and debugging functions.

Underlying principles

1. Bytecode injection: Arthas uses bytecode injection technology to dynamically inject monitoring code and collect performance information by modifying the bytecode of the target Java program. This method does not require recompiling or restarting the application because problems occur after restarting. May not be easily reproducible, so it can be diagnosed and analyzed at runtime.
2. Instrumentation API: Arthas uses Java’s Instrumentation API to implement bytecode injection. This API runs the class loader to modify the bytecode of the class when loading the class. Arthas uses this API to inject its own monitoring code to capture information such as method execution and performance statistics.
3. Agent mode: Arthas runs in the form of Java Agent and is loaded into the target application through the Agent mechanism of JVM. Java Agent is a Java program that runs outside of the Java program and can be dynamically attached to and interact with the application process when the target application is running.

Basic usage

• Since the user executing the Arthas program needs to have the same permissions as the target process, the company’s projects are currently started through containers, so we first need to enter the Java service container, then download the Arthas jar package, and then start it (Windows environment Just run it directly in the CMD window)

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

• After starting, all current Java processes will be listed. We can choose the Java process to monitor according to our own needs.

  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
      # Find a Java process and press the corresponding number key to monitor it
      1
      [INFO] arthas home: /root/.arthas/lib/3.7.1/arthas
      [INFO] The target process already listens to 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]$
  

• So the current requirement is to analyze the time it takes to receive an HTTP request from the Spring framework and then dispatch it to the corresponding Controller method. Here we only need to use trace, a small function of Arthas, which can dynamically calculate the method call path and time consumption. .

  1. The trace method internally calls the path and outputs the time consumption of each node on the method path.
  2. The trace command can actively search class-pattern/method-pattern, the corresponding method path, render and count all performance overhead on the entire call link and trace the call link.

• Understand two more small concepts

  1. DispatcherServlet (org.springframework.web.servlet.DispatcherServlet): DispatcherServlet is the core of Spring MVC. It is responsible for receiving HTTP requests and dispatching the requests to the corresponding Controller. We can start with the request processing method of DispatcherServlet and analyze the call chain and processing time of the request.
  2. HandlerMapping (org.springframework.web.servlet.HandlerMapping): HandlerMapping is responsible for mapping requests to specific Controller methods. You can analyze different HandlerMapping implementations to understand the mapping process of requests to Controller methods.

• Then we now execute trace org.springframework.web.servlet.DispatcherServlet * to analyze what has passed in the call chain

  `---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() method: First, the request enters the doService() method of DispatcherServlet. This is the entry point for request processing. In this method, the following important operations will be performed:
     1. logRequest() method: This method is used to record the requested information, such as the requested HTTP method, URI, etc. It is commonly used for debugging and logging purposes.
     2. isIncludeRequest() method: Check whether the current request is an include request. Containing a request means that a Servlet can contain the response content of another Servlet.
     3. getWebApplicationContext() Method: Get Spring’s Web application context, which contains various bean definitions and configurations in Spring applications.
     4. setAttribute() method: Set some attributes in the HttpServletRequest object so that subsequent processing can access these attributes. This is typically used to pass data during request processing.
     5. getThemeSource() Method: Get theme resources. Themes are usually used to customize the appearance of the application.
  2. doDispatch() method: In doService(), DispatcherServlet calls the doDispatch() method, which is the actual Key methods for request distribution and processing. In this method, the following operations will be performed:
     1. getAsyncManager() Method: Get the asynchronous request manager, used to handle asynchronous requests.
     2. checkMultipart() method: Checks whether the request contains multipart content, usually used for file uploads.
     3. getHandler() method: Get the handler (Handler) used to process the request. This method is the key point in deciding how to handle the request.
        • getHandlerMapping() Method: Get the Handler Mapping used to find the processor. Handler Mapping Maps requests to appropriate handler methods based on the request’s URL or other conditions.
        • Once a suitable handler is found, it is returned for subsequent request processing.
  • Below is a file I uploaded. You can see that most of the time spent is in the checkMultipart() method. When the file upload is abnormally slow next time, you can combine the response time in the Nginx log with the time here. Analyze which step is slow

  `---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
  

  • To analyze the time consumption of a specific method, we only need to clearly specify the fully qualified name of the class and the method name, such as trace com.aimc.paperreduction.web.controller.CommonController uploadPaper, here is the analysis of CommonController The uploadPaper method under the package just added Alibaba Cloud’s text detection before. You can take a look at the impact on performance.

  [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
  

  • From the above results, we can see that Alibaba’s text detection accounts for one-third of the time. We can continue to use the trace command to see why it takes so long.

  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
  

  • It can be seen that the main reason is that TextReview takes a long time, and the creation of the XWPFDocument object is also very performance-intensive. In the code, it is necessary to avoid frequently creating and destroying this object. Continue to look at 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
  

  • locate in code

  TextModerationResponse response = client.textModeration(textModerationRequest);
  

  • This is a synchronous call that will wait for the server to return the result and will block during the waiting period. If the server processing time is long, this code will cause the program to block here forever. The optimization plan is to change this to asynchronous processing
  • In fact, the solution is very simple. The key lies in how to locate and find a solution to the problem. I specially wrote an article to record it.