从频繁告警到平稳发布：服务冷启动 CPU 风暴优化实践

白虹霸天旭日似水流年 發表於 2025-7-24 11:03:00

从频繁告警到平稳发布：服务冷启动 CPU 风暴优化实践

<blockquote data-pm-slice="0 0 []">
作者：vivo 互联网服务器团队- Xie Xiaopeng
 
本文针对服务启动后几分钟内 CPU 持续处于高峰状态的问题，提出了自己的分析思路与解决方案。最终线上效果比较显著，成功解决了每次发版过程中频繁告警、业务受损以及用户体验不佳的问题，为服务的高可用性增添了一道重要保障。本文的重点在于问题的发现、分析及解决思路。对于 CPU 相关的问题，火焰图和 Arthas 是非常有效的工具，建议大家在遇到类似情况时，积极尝试使用这些工具进行排查和解决。
</blockquote>
 
1分钟看图抓住核心观点👇
<img src="https://static001.geekbang.org/infoq/47/47ecd8fbbbcf19a9fd8abc2d5feb3e49.gif">
 
<h1>一、背景</h1>
最近我们的服务在发布或重启时频繁产生告警，这种情况从发版开始一直持续到发版结束后几分钟内，规律非常明显。
 
起初，我们怀疑是流量接入过快导致了此问题。在服务启动后，CICD会检测 check.do 接口，以确认服务是否准备就绪。我们推测，check.do 接口成功返回后，CICD立即接入线上流量，这才引发非常多的异常告警。
 
为了解决这一问题，我们与运维团队进行了沟通，决定将流量接入的时机延迟30秒。延迟30秒后问题还是没有得到解决，告警依然持续不断。
 
<h1>二、问题表象</h1>
以线上某一台机器为例，它的启动步骤如下：
<pre class="highlighter-hljs"><code>2024-09-0416:09:50 INFO - 启动应用，执行成功。
2024-09-0416:12:36 WARN - 检查接口：check.do，响应结果：ok
2024-09-0416:13:07 INFO - 启动后等待时间（秒）：30
2024-09-0416:13:07 INFO - 恢复Dubbo流量成功
2024-09-0416:13:39 INFO - 恢复HTTP流量成功！</code></pre>
 
<h2>2.1 Dubbo 接口超时严重</h2>
恢复HTTP流量后，很多调用下游的Dubbo接口发生超时，以画像接口为例，告警开始时间为：2024-09-04 16:14:07.251，结束时间为：2024-09-04 16:17:31.224，期间超时请求数为：578。
 
<h2>2.2 HTTP 接口超时严重</h2>
大部分HTTP接口也超时严重，P95响应时间从正常的几十毫秒飙升至几秒钟，16:17:30后逐渐恢复至正常水平。
 
<h2>2.3 CPU异常</h2>
服务发布前后CPU表现异常，启动过程CPU存在突刺，接入线上流量后一段时间内CPU使用率将近100%，16:17:30后逐步下降，恢复到正常水平。下图为服务发布前后CPU的使用率截图。
<img src="https://static001.geekbang.org/infoq/d5/d580755c39b9c0cb448cb75ad2f107d5.png">
服务发布前后CPU使用率
 
<h2>2.4 Runnable、Blocked线程突刺</h2>
下图为线程数的相关监控指标，我们可以看到：在服务发布期间，活跃线程数持续增加，启动期间线程剧增，接入线上流量后线程逐步增加，16:17分之后趋于平稳，其中16:12:30-16:12:40期间活跃线程数从249增加到1026（启动期间业务侧有很多任务均会创建线程池，不影响本次分析）
 
Runnable线程数与Blocked线程数也有突刺，时间是16:13:30-16:17:30，与接入HTTP流量时间相符，与CPU突刺时间完全一致。
<img src="https://static001.geekbang.org/infoq/bf/bfa551783893b561054a5356ebad39ff.png">
Runnable线程
 
<img src="https://static001.geekbang.org/infoq/44/4494ccb51f4d5ceb2ba361424d88f385.png">
Blocked线程
 
<h2>2.5 老年代上涨快</h2>
在查看GC老年代内存使用情况时，我们发现启动后未接入流量时，老年代内存为985.84MB。而在接入流量后，截止到16:17:30，内存使用量已经上升至1.36GB，期间老年代的内存增长速度较快。
 
<h2>2.6 下游依赖正常</h2>
从上游视角查看下游依赖的情况，随便挑一个Dubbo接口超时严重的下游依赖，我们查看一下服务的监控指标，发现服务的请求量在启动期间有突刺（业务侧在启动期间会主动发起调用，刷新一些缓存，正常现象），启动后流量几乎没变，但是成功率却有明显下降，且最大响应时间显著增加。
<img src="https://static001.geekbang.org/infoq/13/132d959fd4f96701de6edfa98fce331c.png">
上游视角
 
但是从下游视角再看服务相关指标，接口成功率正常，且最大响应时间也正常，说明不是下游服务的问题。
<img src="https://static001.geekbang.org/infoq/19/19fb81d54c0e53990432ff24b27f619f.png">
下游视角
 
<h1>三、原因初步判断</h1>
从监控数据来看，在线上流量恢复后，我们的服务当前拥有的线程数不足以处理这些业务请求，因此导致系统大量创建业务线程。由于CPU的时间片调度策略，线程之间会频繁发生上下文切换，从而引发CPU负载的剧烈上升，甚至达到饱和状态。
 
因此通过初步分析，我们得到以下结论：
引起CPU飙升的原因主要是由于过多的Runnable状态线程以及频繁的线程上下文切换所导致。我们观察到系统中存在大量已启动的线程，这些线程的状态在Blocked（锁等待、IO等待等）和Runnable之间不断变化。当锁竞争激烈时，CPU飙升的现象就很容易出现。
 
<h1>四、尝试初步解决</h1>
<h2>4.1 流量逐步灰度</h2>
既然我们怀疑是流量全部接入后，线程不足导致的问题，因此需要尝试流量缓慢接入是否能解决这个问题。
我们与运维同学线上随机找了一台机器进行流量灰度实验，具体时间节点如下：
<pre class="highlighter-hljs"><code>2024-09-0509:55:21 启动成功
2024-09-0509:56:17 灰度1%
2024-09-0509:57:19 灰度5%
2024-09-0509:58:31 灰度44%
2024-09-0510:03:51 开始操作全量
2024-09-0510:08:10 全量完成</code></pre>
再观察一下相关指标，我们发现各项指标均正常：CPU使用率不再有突刺，Runnable线程数和Blocked线程数也保持稳定，之前的负载尖峰现象已消失。同时异常超时的日志记录也不再出现，老年代内存的增长速度缓慢，HTTP接口、Dubbo接口P95响应时间正常。由此可见，流量灰度可以解决该问题。
 
① CPU使用率情况如下：
<img src="https://static001.geekbang.org/infoq/4c/4c353a7947276af69dd61d027a414703.png">
CPU使用率
 
② 线程指标情况如下：
<img src="https://static001.geekbang.org/infoq/b5/b5b90ebd0623c04f43e0dee08fed0f50.png">
Runnable线程
 
<img src="https://static001.geekbang.org/infoq/3f/3f1e58d3f15653c5803322dda23c24aa.png">
Blocked线程
 
<h2>4.2 缓存预热</h2>
在前文中提到，接入线上流量后，老年代的内存增长较快，因此我们推测在服务启动初期，由于尚未加载相关的缓存数据，当大量请求涌入时，未命中缓存的情况频繁发生，这迫使系统不断向下游请求以加载缓存，从而导致接口响应变慢。为此，我们需要验证预热缓存的有效性，以确定是否能够改善这一问题。
 
缓存预热的主要作用和目的如下：
<ul>
<li>
提高缓存命中率：通过预先加载热点数据，能够显著提升缓存的命中率，从而减少对后端数据源（如数据库）的访问，降低系统负载。
</li>
<li>
保持服务性能稳定：在服务启动或缓存失效之后，缓存预热可以有效防止请求对后端数据源施加突发压力，从而确保服务性能的稳定性。
</li>
<li>
优化用户体验：由于热点数据已被预先加载到缓存中，用户在请求这些数据时能够获得更快的响应速度，从而显著提升用户体验。
</li>
</ul>
 
方案如下：
我们将梳理本地缓存信息，根据访问量和缓存大小区分数据的重要程度，定期将重要的缓存信息刷新至Redis中。在服务启动后，未接入线上流量之前，我们将优先从Redis中进行数据的预加载。通过这一措施，确保系统在高流量环境下的稳定性和性能。
 
实验结果显示，增加缓存预热后，问题并未得到有效解决，表现差异微乎其微。
 
仅仅预热重要缓存无法解决当前问题。系统在启动时需要预热的内容相对较多，同时各类中间件也有自身的缓存需要预热。因此仅预热业务自定义的内存缓存，效果非常有限。
 
回顾之前的原因分析，我们仅仅关注了表面现象，如CPU的上涨和线程数的增加，而未深入挖掘问题的本质。我们需要探讨线程数为何上升、CPU为何飙升，接下来将进行更深入的分析，以找出问题的根本原因。
 
<h1>五、分析问题</h1>
<h2>5.1 初步分析堆栈与CPU火焰图</h2>
我们选择了一台线上机器进行服务重启，并在接入线上流量后的几分钟内导出了程序的线程堆栈信息，进行分析：
<ul>
<li>
Runnable 线程数显著增多，占比达到29%，通常情况下，Runnable线程数约为70个，而此时却激增至462个；
</li>
<li>
进一步查看 Runnable 线程，发现大部分线程为 catalina-exec 线程（380个），这是Tomcat用于执行Spring MVC应用中Servlet请求的线程。正常情况下，这类线程的数量仅有几个；
</li>
<li>
在这些Runnable线程中，有201个线程均被阻塞在 org.springframework.beans.PropertyMatches.calculateStringDistance(PropertyMatches.java:170) 这个方法上，我们需要进一步分析其原因。
</li>
</ul>
看了堆栈信息后，应该有个疑问：为什么启动了这么多的tomcat线程？
 
我们推测原因在于服务刚启动时，系统尚未加载任何缓存，所有数据都需要进行首次加载。在这种情况下，服务无法快速响应用户请求，导致接口的响应时间（RT）显著上升。在相同的QPS的情况下，为了处理不断增加的业务请求，系统不得不创建更多的Tomcat线程。
 
接下来我们接入Arthas工具，采集CPU火焰图以进行深入分析，CPU火焰图如下：
<img src="https://static001.geekbang.org/infoq/d1/d16a4976e7833c4040e27060cf99a1d8.png">
异常CPU火焰图
 
分析结果显示，CPU耗时主要集中在calculateStringDistance方法，这与我们之前的线程堆栈分析结果一致。在服务启动时的CPU火焰图中，calculateStringDistance方法的CPU消耗占比高达16.68% + 39.09% + 8.38% = 64.15%，整体CPU使用率接近97%。
 
经过一段时间的运行后，再观察正常情况下的CPU火焰图，calculateStringDistance方法的CPU消耗占比降至3.39% + 8.57% + 1.78% = 13.74%，整体CPU使用率则徘徊在25%至42%之间。
 
这一变化表明，随着系统的稳定运行，CPU负载逐渐得到缓解，但calculateStringDistance方法仍然是性能瓶颈之一。它虽然不是CPU使用率飙升的根因，但它在服务启动后进一步加剧了CPU的负载。
 
<h3>5.1.1 calculateStringDistance加剧CPU暴涨</h3>
在相同QPS的情况下，为什么在服务启动后的几分钟内calculateStringDistance方法消耗的CPU资源严重，而经过一段时间后，这一消耗又有所减小？
 
前文的分析指出，服务刚启动时，流量瞬间恢复，导致系统需要创建大量的业务线程。这些线程在处理请求时，都会执行calculateStringDistance方法。由于该方法本身的计算开销较大，且并发执行的线程数量越多，CPU的消耗就会越显著。因此在服务启动初期，CPU的负载急剧上升。随着运行时间的延长，业务线程的创建和执行也趋于平衡，并发执行的线程数量大大减小，CPU消耗也随之减小。
 
<h3>5.1.2 calculateStringDistance源码分析</h3>
calculateStringDistance方法的功能是根据Levenshtein算法计算给定两个字符串之间的距离或相似度。通过分析其源代码，我们可以发现，在比较两个字符串时，该方法采用了嵌套的for循环结构。在这些循环中，涉及到length、chatAt和Math.min函数的调用，这使得该方法的计算复杂度相对较高。调用量越大，CPU消耗就会越严重。根据CPU火焰图的分析，发现这三个函数的CPU消耗占比与calculateStringDistance方法的CPU消耗占比之间的比例高达78%。因此在调用该方法时要小心，在高并发场景下，该方法很有可能成为系统的性能瓶颈，对CPU产生影响。
<pre class="highlighter-hljs"><code>private static int calculateStringDistance(String s1, String s2){
  if (s1.isEmpty()) {
    return s2.length();
  }
  if (s2.isEmpty()) {
    return s1.length();
  }

  int[][] d = newint;
  for (int i = 0; i <= s1.length(); i++) {
    d = i;
  }
  for (int j = 0; j <= s2.length(); j++) {
    d = j;
  }

  for (int i = 1; i <= s1.length(); i++) {
    char c1 = s1.charAt(i - 1);
    for (int j = 1; j <= s2.length(); j++) {
      int cost;
      char c2 = s2.charAt(j - 1);
      if (c1 == c2) {
        cost = 0;
      }
      else {
        cost = 1;
      }
      d = Math.min(Math.min(d + 1, d + 1), d + cost);
    }
  }

  return d;
}
}</code></pre>
 
calculateStringDistance方法是如何触发的？通过查询堆栈信息并查看源代码，我们发现这是Spring框架在解析请求参数并注入属性的过程中所触发的。堆栈信息如下，从上到下逐步分析堆栈，我们重点分析setPropertyValues和createNotWritable-
PropertyException这两个方法。
<pre class="highlighter-hljs"><code>"catalina-exec-485" #975 daemon prio=5 os_prio=0 tid=0x00007f50e825f000 nid=0x3375 runnable
   java.lang.Thread.State: RUNNABLE
      at org.springframework.beans.PropertyMatches.calculateStringDistance(PropertyMatches.java:170)
      at org.springframework.beans.PropertyMatches.access$100(PropertyMatches.java:44)
      at org.springframework.beans.PropertyMatches$BeanPropertyMatches.calculateMatches(PropertyMatches.java:208)
      at org.springframework.beans.PropertyMatches$BeanPropertyMatches.<init>(PropertyMatches.java:193)
      at org.springframework.beans.PropertyMatches.forProperty(PropertyMatches.java:68)
      at org.springframework.beans.PropertyMatches.forProperty(PropertyMatches.java:58)
      at org.springframework.beans.BeanWrapperImpl.createNotWritablePropertyException(BeanWrapperImpl.java:237)
      at org.springframework.beans.AbstractNestablePropertyAccessor.processLocalProperty(AbstractNestablePropertyAccessor.java:435)
      at org.springframework.beans.AbstractNestablePropertyAccessor.setPropertyValue(AbstractNestablePropertyAccessor.java:290)
      at org.springframework.beans.AbstractNestablePropertyAccessor.setPropertyValue(AbstractNestablePropertyAccessor.java:278)
      at org.springframework.beans.AbstractPropertyAccessor.setPropertyValues(AbstractPropertyAccessor.java:95)
      at org.springframework.validation.DataBinder.applyPropertyValues(DataBinder.java:860)
      at org.springframework.validation.DataBinder.doBind(DataBinder.java:756)
      at org.springframework.web.bind.WebDataBinder.doBind(WebDataBinder.java:192)
      at org.springframework.web.bind.ServletRequestDataBinder.bind(ServletRequestDataBinder.java:106)
      at org.springframework.web.servlet.mvc.method.annotation.ServletModelAttributeMethodProcessor.bindRequestParameters(ServletModelAttributeMethodProcessor.java:152)
      at org.springframework.web.method.annotation.ModelAttributeMethodProcessor.resolveArgument(ModelAttributeMethodProcessor.java:111)
      at org.springframework.web.method.support.HandlerMethodArgumentResolverComposite.resolveArgument(HandlerMethodArgumentResolverComposite.java:121)
      at org.springframework.web.method.support.InvocableHandlerMethod.getMethodArgumentValues(InvocableHandlerMethod.java:158)
      at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest$original$3Q7HrFjh(InvocableHandlerMethod.java:128)
      at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest$original$3Q7HrFjh$accessor$ykGmQRZT(InvocableHandlerMethod.java)
      at org.springframework.web.method.support.InvocableHandlerMethod$auxiliary$Wny4v5BZ.call(Unknown Source)
      at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java)
      at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97)
      at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:849)
      at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:760)
      at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
      at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967)
      at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901)
      at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
      at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:650)
      at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:347)
      at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:263)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:347)
      at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:263)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197)
      at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
      at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
      at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
      at org.apache.catalina.core.StandardWrapperValve.invoke$original$Y7IhKDGv(StandardWrapperValve.java:219)
      at org.apache.catalina.core.StandardWrapperValve.invoke$original$Y7IhKDGv$accessor$4IDmuys6(StandardWrapperValve.java)
      at org.apache.catalina.core.StandardWrapperValve$auxiliary$1SL1DIkO.call(Unknown Source)
      at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java)
      at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:110)
      at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:494)
      at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:169)
      at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:104)
      at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
      at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:445)
      at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1136)
      at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:637)
      at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1775)
      at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1734)
      - locked <0x000000070f1dc100> (a org.apache.tomcat.util.net.NioChannel)
      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
      at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
      at java.lang.Thread.run(Thread.java:748)</code></pre>
 
先分析setPropertyValues方法，该方法负责将请求中的参数映射到目标对象的属性上，主要是遍历属性列表进行赋值并进行异常统一处理，单个属性的注入继续看setPropertyValue方法。
<pre class="highlighter-hljs"><code>public void setPropertyValues(PropertyValues pvs, boolean ignoreUnknown, boolean ignoreInvalid)
      throws BeansException {
    // 声明PropertyAccessException集合，保存单个属性注入时抛出的PropertyAccessException异常
  List<PropertyAccessException> propertyAccessExceptions = null;
    // 获取属性列表
  List<PropertyValue> propertyValues = (pvs instanceof MutablePropertyValues ?
      ((MutablePropertyValues) pvs).getPropertyValueList() : Arrays.asList(pvs.getPropertyValues()));
  for (PropertyValue pv : propertyValues) {
    try {
      // 单个属性的注入，注意：此方法可能会引发任意的BeansException，如果存在严重故障（例如没有匹配的字段），则不会在此处捕获该异常。我们可以尝试只处理不太严重的异常。
      setPropertyValue(pv);
    }
    catch (NotWritablePropertyException ex) {
            // 默认是true，忽略未知属性，因此不会抛异常
      if (!ignoreUnknown) {
        throw ex;
      }
      // Otherwise, just ignore it and continue...
    }
    catch (NullValueInNestedPathException ex) {
      if (!ignoreInvalid) {
        throw ex;
      }
      // Otherwise, just ignore it and continue...
    }
    catch (PropertyAccessException ex) {
      if (propertyAccessExceptions == null) {
        propertyAccessExceptions = new LinkedList<PropertyAccessException>();
      }
      propertyAccessExceptions.add(ex);
    }
  }

  // 如果 propertyAccessExceptions 不为空，需要整合起来，抛一个复合异常 PropertyBatchUpdateException
  if (propertyAccessExceptions != null) {
    PropertyAccessException[] paeArray =
        propertyAccessExceptions.toArray(new PropertyAccessException);
    thrownew PropertyBatchUpdateException(paeArray);
  }
}</code></pre>
 
propertyValues 属性的结构如下，它包含了从上游传递过来的所有参数。这些参数被封装成一个集合，便于后续的处理和注入。
<img src="https://static001.geekbang.org/infoq/b8/b8be43e3b179400cba74add7522acecb.png">
propertyValues 属性
 
分析setPropertyValue方法，该方法主要作用是解析属性值，如果存在嵌套属性，则递归解析设置最终对应的属性值，方法最后都会调用setPropertyValue(tokens, pv)方法。
<pre class="highlighter-hljs"><code>public void setPropertyValue(PropertyValue pv) throws BeansException {
  PropertyTokenHolder tokens = (PropertyTokenHolder) pv.resolvedTokens;
  if (tokens == null) {
    String propertyName = pv.getName();
    AbstractNestablePropertyAccessor nestedPa;
    try {
           // 确定给定属性路径中的第一个嵌套属性分隔符，忽略键中的点（如 “map”）。
         // 当配置的属性名propertyName中包含'.'这样字符时，代表需要设置嵌套属性
       // 如果存在嵌套属性，Spring会递归向下获取最终设置的属性，比如：a.b.c，Spring会递归调用获取到b，c是需要设置的属性
       // 如果没有嵌套属性的话。会返回自身
      nestedPa = getPropertyAccessorForPropertyPath(propertyName);
    }
    catch (NotReadablePropertyException ex) {
      thrownew NotWritablePropertyException(getRootClass(), this.nestedPath + propertyName,
          "Nested property in path '" + propertyName + "' does not exist", ex);
    }
        // 将给定的属性名称解析为相应的属性名称令牌，如果没有[]，则tokens中的keys为空，且actualName、canonicalName都等于 propertyName 
    tokens = getPropertyNameTokens(getFinalPath(nestedPa, propertyName));
    if (nestedPa == this) {
      pv.getOriginalPropertyValue().resolvedTokens = tokens;
    }
        // 设置属性
    nestedPa.setPropertyValue(tokens, pv);
  }
  else {
       // 设置属性
    setPropertyValue(tokens, pv);
  }
}</code></pre>
 
分析setPropertyValue(tokens, pv)方法，该方法是用来区分数组类型跟非数组类型的，大部分属性都是非数组类型，我们分析非数组类型方法。
<pre class="highlighter-hljs"><code>protected void setPropertyValue(PropertyTokenHolder tokens, PropertyValue pv) throws BeansException {
    // 如果属性中存在[]，说明是数组，则进入该方法
  if (tokens.keys != null) {
    processKeyedProperty(tokens, pv);
  }
  else {
        // 大部分都走这个方法
    processLocalProperty(tokens, pv);
  }
}</code></pre>
 
processLocalProperty方法的作用就是获取属性值，利用反射完成属性注入。
<pre class="highlighter-hljs"><code>private void processLocalProperty(PropertyTokenHolder tokens, PropertyValue pv){
    // 获取属性对应的 PropertyHandler
  PropertyHandler ph = getLocalPropertyHandler(tokens.actualName);
    // 如果不存在对应的handler 或者属性是不可写的（没有setter方法）
  if (ph == null || !ph.isWritable()) {
        // 如果属性是optional类型，则直接返回
    if (pv.isOptional()) {
      if (logger.isDebugEnabled()) {
        logger.debug("Ignoring optional value for property '" + tokens.actualName +
            "' - property not found on bean class [" + getRootClass().getName() + "]");
      }
      return;
    }
    else {
      // 其他情况则抛出不可写属性异常，占用CPU较多的方法由此进入
      throw createNotWritablePropertyException(tokens.canonicalName);
    }
  }

  Object oldValue = null;
  try {
        // 获取属性值
    Object originalValue = pv.getValue();
    Object valueToApply = originalValue;
        // 如果需要转换，则进入此分支
    if (!Boolean.FALSE.equals(pv.conversionNecessary)) {
      // 如果已经完成类型转换，则直接使用
      if (pv.isConverted()) {
        valueToApply = pv.getConvertedValue();
      }
      else {
        // 如果需要读取旧值，默认是false && 值可读（有getter方法）
        if (isExtractOldValueForEditor() && ph.isReadable()) {
          try {
            oldValue = ph.getValue();
          }
          catch (Exception ex) {
            if (ex instanceof PrivilegedActionException) {
              ex = ((PrivilegedActionException) ex).getException();
            }
            if (logger.isDebugEnabled()) {
              logger.debug("Could not read previous value of property '" +
                  this.nestedPath + tokens.canonicalName + "'", ex);
            }
          }
        }
        // 类型转换
        valueToApply = convertForProperty(
            tokens.canonicalName, oldValue, originalValue, ph.toTypeDescriptor());
      }
      pv.getOriginalPropertyValue().conversionNecessary = (valueToApply != originalValue);
    }
    // 完成属性注入
    ph.setValue(this.wrappedObject, valueToApply);
  }
  catch (TypeMismatchException ex) {
    throw ex;
  }
  catch (InvocationTargetException ex) {
    PropertyChangeEvent propertyChangeEvent = new PropertyChangeEvent(
        this.rootObject, this.nestedPath + tokens.canonicalName, oldValue, pv.getValue());
    if (ex.getTargetException() instanceof ClassCastException) {
      thrownew TypeMismatchException(propertyChangeEvent, ph.getPropertyType(), ex.getTargetException());
    }
    else {
      Throwable cause = ex.getTargetException();
      if (cause instanceof UndeclaredThrowableException) {
        // May happen e.g. with Groovy-generated methods
        cause = cause.getCause();
      }
      thrownew MethodInvocationException(propertyChangeEvent, cause);
    }
  }
  catch (Exception ex) {
    PropertyChangeEvent pce = new PropertyChangeEvent(
        this.rootObject, this.nestedPath + tokens.canonicalName, oldValue, pv.getValue());
    thrownew MethodInvocationException(pce, ex);
  }
}</code></pre>
 
在该方法中，我们注意到堆栈信息中createNotWritablePropertyException方法的调用。实际上calculateStringDistance方法的高CPU消耗正是由此引发的。当抛出不可写属性异常时，系统会计算字符串的相似度，主要目的是为了向用户提供更友好的提示，帮助他们识别哪些属性与当前属性相似，从而判断是否在传递参数时出现了错误。
 
Spring这种设计不仅提升了用户体验，还降低了因参数错误而导致的调试难度。通过提供相似属性的建议，用户能够更快速地发现并纠正输入错误，确保请求的正确性。以下为调试过程中的部分提示：
<pre class="highlighter-hljs"><code>Bean property 'questionValidatorInterface' is not writable or has an invalid setter method. Does the parameter type of the setter match the return type of the getter?
bean property 'users' is not writable or has an invalid setter method. did you mean 'user'?</code></pre>
 
<h3>5.1.3 calculateStringDistance流程总结</h3>
结合Spring MVC解析HTTP的请求流程，calculateStringDistance方法的进入流程如下：
<img src="https://static001.geekbang.org/infoq/98/980b1eec282687524d8db9ecd78be00a.png">
解析参数流程
 
Spring MVC在解析HTTP请求参数时会找到对应的参数解析器，因为我们的项目中大部分都是自定义的复杂对象，因此采用的参数解析器为ServletModelAttributeMethodProcessor。该解析器在数据绑定过程中，会循环遍历每个参数，通过反射完成属性注入。但是我们自定义的复杂对象在某些接口下，定义的属性不合理，导致抛出createNotWritablePropertyException异常。
 
我们深入分析一下源码，看看怎样避免抛出createNotWritablePropertyException异常。
 
根据源码，我们发现抛出不可写属性异常的条件是（属性不存在对应的handler 或者属性不可写）并且属性不是optional类型，只要我们保证不满足这个条件，那么就可以有效避免抛出该异常。
 
说明一下这三个条件：
<ul>
<li>
属性不存在对应的handler 即 request中不存在该属性。比如请求参数中带version字段，但是服务端在接受request中并未定义version字段，那么此处ph == null判断条件就成立
</li>
<li>
属性不可写，即属性没有对应的setter方法
</li>
<li>
属性是optional类型，即属性的数据类型是Optional类型
</li>
</ul>
通过查看业务侧的代码，我们发现请求（request）中的所有属性都已经定义了相应的 setter 方法，而且不存在optional类型的属性。因此我们只需要关注请求中是否存在未定义的属性。
 
<h3>5.1.4 排查大流量及核心接口参数</h3>
由于服务提供的接口非常多，因此仅排查流量较高和核心的接口。经过分析，我们发现几乎所有接口都存在未定义的属性。
 
这主要是因为客户端很多参数都是公参，在传参时会将这些公参全部透传给服务端，但是服务端并不需要处理所有的参数，因此没有在request中定义。特别备注：接口若未定义请求参数接收，则不会走上述流程。
 
<h3>5.1.5 解决方案</h3>
既然已经明确问题的根源是请求中存在未定义的属性，那么接下来我们将针对这一情况进行优化。方案主要有两个：
<blockquote>
<ol>
<li>
在底层请求中加入客户端公参：对所有公参进行接收，确保它们能够被正确处理。需要注意的是，参数接收将会涉及属性注入，而属性注入是通过反射机制实现的。这一过程可能对CPU和接口性能产生影响，因此我们也需要进行实验，以评估这些参数解析的实际效果。
</li>
<li>
在filter层针对接口去除相关字段：通过在过滤器层面过滤掉不必要的字段，避免接口中出现未定义的属性。
</li>
</ol>
</blockquote>
 
最终我们混合两种方案：对于大部分公共参数，定义到底层request中；对于非公共参数，针对接口进行移除。
 
我们针对大流量接口及核心接口进行了优化，优化后效果如下：
 
结论：整体效果显著，但仍存在一些不足之处。
<ul>
<li>
CPU使用情况：在高峰期重启应用时，CPU的突发情况明显减弱，持续时间从5分钟缩短至1分钟。同时CPU和Runnable线程数仍会出现小幅波动，但Runnable线程数的波动持续时间已从6分钟缩减至40秒，波动峰值也由600降低至280。
</li>
<li>
接口性能：接口的P95和P99耗时均有所降低，其中P95峰值从53秒降至3.4秒，P99峰值从1分50秒降至50秒。此外，响应时间较长的时间段也得到了缩短，持续时间从7分钟减少到不到2分钟。
</li>
<li>
发版及日常运行：在发版期间及日常运行中，CPU峰值普遍降低。与前1天和前7天的平均CPU使用率相比，最大和最小使用率均有所下降，幅度明显。
</li>
</ul>
 
① 启动后CPU使用率情况如下：
<img src="https://static001.geekbang.org/infoq/39/392a94c6a3d5e34993183bd0f304d2b0.png">
CPU使用率
 
② 线程数情况如下：
<img src="https://static001.geekbang.org/infoq/bc/bc586c8ed8eb75aff68d6c8af1f3f169.png">
Runnable线程数
 
<img src="https://static001.geekbang.org/infoq/67/6752d82ddfcd92632af91a7d573023dd.png">
Blocked线程数
 
③ 接口响应时间情况如下：
 
<img src="https://static001.geekbang.org/infoq/1f/1f7f243ad16cd06f20e167312e46a331.png">
接口响应时间
 
④ 运行一段时间后，CPU使用率情况如下：
<img src="https://static001.geekbang.org/infoq/7d/7dc2dfcce68536de17cc8fe2f9528f3b.png">
CPU使用率
 
<h2>5.2 优化后再次分析CPU火焰图</h2>
优化后效果虽然好了很多，但是CPU和Runnable线程数仍会出现小幅波动，接口的响应时间在1分钟内仍有上涨。这是我们接下来要继续优化的目标。
 
<h3>5.2.1 编译阶段消耗CPU占比高</h3>
再次使用arthas进行监测，查看正常情况与启动后（异常情况）的CPU消耗情况，我们可以观察到：
<ul>
<li>
runWoker部分：
</li>
</ul>
该部分的 CPU 占用比例正常，与平时的表现一致，未见异常波动。
<ul>
<li>
编译相关的CPU占用：
</li>
</ul>
CompileBroker::invoke_compiler_on_method(CompileTask*) 占用CPU较大，特别是C2Compiler::compile_method(ciEnv*, ciMethod*, int)的占比显著
 
由此我们得出结论：编译阶段的 CPU 消耗占比异常，可能是导致CPU负载突刺的重要因素。
 
① 异常情况下CPU火焰图：
<img src="https://static001.geekbang.org/infoq/82/82b6012b6cda9ad352cbfc08b03f198f.png">
异常CPU火焰图
 
② 正常情况下CPU火焰图：
<img src="https://static001.geekbang.org/infoq/f2/f20b40d852d10a7a24376bf48cb4eaab.png">
正常CPU火焰图
 
<h3>5.2.2 用arthas换个角度验证</h3>
CPU 火焰图是基于启动后 3 分钟内的综合数据采集而生成的，虽然能够提供整体的 CPU 使用情况，但无法反映 CPU 的实时变化。因此，为了更准确地验证编译阶段是否确实消耗了 CPU，我们需要登录到机器上，使用 Arthas 进行实时监测。
 
机器启动后，运行dashboard命令，重点关注屏幕上方的进程信息，以识别哪些线程占据了较高的CPU资源，以下为其中一次波动的截图，前几次波动CPU占比都差不多：
<img src="https://static001.geekbang.org/infoq/fb/fb3410588e2c28c64fdc8140a09eacfd.png">
dashboard命令
 
从图中可以看到， CompilerThread 的三个线程占用了较高的 CPU 资源，尤其是 C2 CompilerThread 的占比明显，这与之前通过火焰图所反映的情况一致。
 
<h3>5.2.3 CompilerThread是什么</h3>
C1 C2 CompilerThread 是 Java HotSpot 虚拟机中的两个即时编译器，主要作用是将 Java 字节码在运行时编译成本地机器码，以提高程序的执行效率。
<ul>
<li>
C1 Compiler（也称为客户端编译器），主要用于快速编译，优化较少，适合需要快速启动的应用。它的编译速度较快，但生成的机器码执行效率相对较低。
</li>
<li>
C2 Compiler（也称为服务端编译器），主要用于高性能的编译，优化程度较高，适合长时间运行的应用。C2 编译器会花费更多时间进行优化，以生成更高效的机器码，适合对性能要求较高的场景。
</li>
</ul>
 
在HotSpot虚拟机中，Java程序最初都是通过解释器（Interpreter）进行解释执行的，解释器的优点是启动快，省去编译的时间，能够快速运行代码。但随着程序的执行，某些方法或代码块可能会被多次调用，这些被频繁调用的代码被称为“热点代码”（Hot Spot Code）。当虚拟机识别到热点代码时，它会启动 JIT 编译器（C1 或 C2）将这些代码编译成本地机器码，以提高执行效率。
 
HotSpot虚拟机是解释器与即时编译器并存的架构，两者经常是相辅相成地配合工作。由于即时编译器编译本地代码需要占用程序运行时间，编译出优化程度更高的代码所需的时间也会相应增加。此外为了实现更高的优化，解释器需要为编译器收集性能监控信息，这在一定程度上也会影响解释执行阶段的速度。为了解决这一问题，并在程序启动响应速度与运行效率之间达到最佳平衡，HotSpot 虚拟机在其编译子系统中引入了分层编译的功能。通过这一机制，HotSpot 能够根据代码的执行频率和性能需求，逐步将字节码编译为本地机器码，从而在保证快速启动的同时，优化长时间运行的代码性能。
 
<h3>5.2.4 解决方案</h3>
截止到现在，问题的原因就变得十分清晰了：当流量涌入时，HotSpot 虚拟机启动了分层编译机制，期间大部分代码迅速转变为热点代码。在这个过程中，C2 编译器需要频繁占用 CPU 资源进行编译，导致 CPU 使用率显著上升。随着大部分热点代码的优化完成，C2 编译器对 CPU 的占用将逐渐减少，CPU 使用率也会随之下降。这一编译过程的持续时间与监控图上的 CPU 波动情况高度一致。
 
C1 和 C2 编译器虽然提供了关闭的参数选项，但关闭这些编译器无疑会对服务的运行性能产生负面影响。网络上也有相关实验案例表明，对于需要长期运行的 Java 后端服务，禁用这些编译器将导致性能显著下降。因此这种关闭编译器的方式并不值得尝试。
 
解决方案一：
在前文中，我们已经验证了流量逐步放量对机器的影响：采用灰度发布，对机器几乎没什么影响，各项指标表现都很平稳。由于历史原因，我们的服务当前无法支持灰度发布，因此还需要探索其他有效的解决方案。
 
我们可以换个角度思考：是否可以通过降低接口的请求 QPS，并将发版时间固定在每天流量最低的时段，以观察对服务启动的影响。
 
首先，我们可以优先关注大流量接口，并尝试减少这些接口的 QPS。通过优化接口请求的频率，我们或许能够在发版过程中减轻对系统的压力。
 
降低接口QPS，调整重启服务的时间（非高峰期），12:13:59 恢复流量成功，实验效果如下：
<ul>
<li>
恢复流量后CPU最高峰值为61.5%（依旧有小突刺，但是对业务无影响）
</li>
<li>
Runnable、Blocked线程数不再有突刺
</li>
<li>
接口响应时间（RT）也比较平稳
</li>
<li>
日志不再告警，无error错误日志
</li>
</ul>
 
① CPU使用率情况如下：
<img src="https://static001.geekbang.org/infoq/53/53b3325d85e1325b0ddc8d435867d602.png">
CPU使用率
 
② 线程指标如下：
<img src="https://static001.geekbang.org/infoq/ee/ee1257640a2152206cd5c040cabca908.png">
Runnable线程数
 
<img src="https://static001.geekbang.org/infoq/1e/1ec1937483051c10f4ee7353131f10e3.png">
Blocked线程数
 
③ 接口响应时间情况如下：
<img src="https://static001.geekbang.org/infoq/65/65ccf93c952fc85c1788e28907539ff8.png">
接口响应时间
 
解决方案二：
方案一虽然能够在一定程度上缓解问题，但治标不治本。此外我们也无法固定发版时间，因此最有效的策略是进行预热。与前文不同的点在于，此处是JVM预热。
 
方案为：在系统成功启动（监测check.do返回成功）后，接入线上HTTP流量之前，针对大流量接口及核心接口进行HTTP接口调用，频控次数为配置项，方便线上动态调整。特别注意：在刚启动时，如果机器或下游依赖出现故障，此处的额外调用会加剧系统或下游的负担，因此调用次数需要合理配置。
 
此方式可以让C2 编译器提前对热点代码进行优化，在系统在系统稳定后再将流量接入生产环境，从而避免对用户造成任何影响。
 
观察启动后的各项指标，14:56:25 恢复HTTP流量成功，实验效果如下：
 
整体表现与之前的方案一相似，但是有一个显著的区别：在恢复 HTTP 流量之前，Runnable 线程数出现了明显的突刺，而在流量恢复后，这种突刺现象则不再出现，线程数已经趋于平稳。我们注意到突刺出现的时间节点是14:55:25，这个时间点正好是我们预热时发起HTTP接口调用的时间。
 
这表明通过预热策略，我们有效地前置了系统的负载波动。当真正的用户请求到达时，系统已经趋于平稳，服务响应速度保持稳定，从而为用户提供了更加流畅的体验。
 
① CPU使用率情况如下：
<img src="https://static001.geekbang.org/infoq/d3/d3d681d104fe45f2c3ccfb55a4d7349a.png">
CPU使用率
 
② 线程指标如下：
<img src="https://static001.geekbang.org/infoq/0b/0badd50a03479a470d5972b9742f131d.png">
Runnable线程数
 
<img src="https://static001.geekbang.org/infoq/91/91d82c3a294a0a04683e3d0c7539e491.png">
Blocked线程数
 
<h1>六、总结</h1>
本文针对服务启动后几分钟内 CPU 持续处于高峰状态的问题，提出了自己的分析思路与解决方案。最终线上效果比较显著，成功解决了每次发版过程中频繁告警、业务受损以及用户体验不佳的问题，为服务的高可用性增添了一道重要保障。最初的分析不够深入，导致在内存缓存预热方面的努力未能产生预期效果。因此在未来遇到类似问题时，我们必须深入挖掘，直至找到问题的根本原因。
 
本文的重点在于问题的发现、分析及解决思路。对于 CPU 相关的问题，火焰图和 Arthas 是非常有效的工具，建议大家在遇到类似情况时，积极尝试使用这些工具进行排查和解决。
 
此外HTTP 请求未定义属性的问题普遍存在，特别是在服务未进行预热启动时，会加剧 CPU 的负载。对于大流量服务而言，遇到此类问题时，需规范请求参数，以减轻CPU负担。

</div>
<div id="MySignature" role="contentinfo">
分享 vivo 互联网技术干货与沙龙活动，推荐最新行业动态与热门会议。 
来源：https://www.cnblogs.com/vivotech/p/19002355

頁: [1]

琼殿技术论坛's Archiver

从频繁告警到平稳发布：服务冷启动 CPU 风暴优化实践