SpringBoot使用Arthas做性能分析及生产环境热更新

感谢

这片文章首先需要感谢，一起共同参与排查的同事们，没有他们也没法完成分析。
最终问题并没有得到解决，如果解决了我希望运维的同学对网络上做些分享,以弥补本文的缺陷。

背景

目前所有的Java应用，在Kubernetes中使用Spring Boot Actuator的作为健康检查和就绪检查，实际使用过程中碰到了一些问题：

1. 某些中间件邮件实现方式问题，导致中间件压力过大（资源评估不足），导致检查失败
2. 单纯性某些节点出现HTTP请求超时的情况（偶发），且服务无压力，线程池非常空闲

对于问题1，我们评估后关闭了相关可能导致中间件压力过大的情况解决，但是对于问题2就比较困难了，这篇文章介绍了我们分析解决过程中使用的方法和工具，其中Arthas成为最后的杀手锏（没办法线上环境，如果使用重启的方式进行排查时间将不可预期，且没法一次性解决）

故事

生产事故

生产系统出现问题，大家都在排出不是自己的问题（我也醉了），两个机房，其中一个机房比另外一个机房出现的服务多，健康检查我们推行的方案，所有我们得出解决方案。
其中一个开发的同学说：没上健康检查，服务都没有重启那么多次。我只是想表达，健康检查出现的低频率的访问，对系统就有压力了，请求量真上去了，服务还有服务能力吗？

介入排查

我们从以下方面进行了排查

1. 主节点是否存在压力，CPU，内存磁盘稳定，排除
2. 服务是否存在GC情况，从中断的时间的日志、监控，排除
3. 服务是否存在处理并发问题，从监控看，存在空闲线程，且没有到最大值，排除
4. POD是否存在网络带宽，磁盘IO繁忙，从监控分平均不受影响，排除

怎么一个简单的健康检查在服务压力不大的工作节点上，出现延时（不是错误，没有一点日志可供分析），已经超出的了我的认知。

同一时间点，从Kubernetes的健康检查验证上分析，是由于健康检查超时导致（使用命令行【curl】的方式很难得到正确的结果），对比监控的返回时间监控可以判断是健康检查的处理超时导致健康检查失败，导致的一序列问题，但从排查的结果来看，没有解决方案了（重启算一种解决方案吗？），出于对问题的探索，我想到了热力图，从百度结果看，把我引向了阿里的Arthas，它是否能解决我目前的问题呢？我就来尝试下。

Arthas

我们是科技的搬运工，记得文档一定以官方为准，不要在本文档copy。
Arthas官方文档：https://arthas.aliyun.com/doc/#
Arthas在线教程：https://arthas.aliyun.com/doc/arthas-tutorials.html?language=cn

Arthas（阿尔萨斯） 能为你做什么？

Arthas 是Alibaba开源的Java诊断工具，深受开发者喜爱。
当你遇到以下类似问题而束手无策时，Arthas可以帮助你解决：

1. 这个类从哪个 jar 包加载的？为什么会报各种类相关的 Exception？
2. 我改的代码为什么没有执行到？难道是我没 commit？分支搞错了？
3. 遇到问题无法在线上 debug，难道只能通过加日志再重新发布吗？
4. 线上遇到某个用户的数据处理有问题，但线上同样无法 debug，线下无法重现！
5. 是否有一个全局视角来查看系统的运行状况？
6. 有什么办法可以监控到JVM的实时运行状态？
7. 怎么快速定位应用的热点，生成火焰图？
8. 怎样直接从JVM内查找某个类的实例？

Arthas支持JDK 6+，支持Linux/Mac/Windows，采用命令行交互模式，同时提供丰富的 Tab 自动补全功能，进一步方便进行问题的定位和诊断。

本来只想找个火焰图工具，结果让我们找到了一个全新的解决方案。

全量安装

为什么呢？生产环境，无法没尽兴在线安装。

最新版本，点击下载：https://arthas.aliyun.com/download/latest_version?mirror=aliyun
解压后，在文件夹里有arthas-boot.jar，直接用java -jar的方式启动：
java -jar arthas-boot.jar

打印帮助信息：
java -jar arthas-boot.jar -h

分析

Arthas在线分析

$ java -jar arthas-boot.jar
[INFO] arthas-boot version: 3.5.2
[INFO] Found existing java process, please choose one and input the serial number of the process, eg : 1. Then hit ENTER.
* [1]: 36 <you application>.jar

选择第一个进程，输入 1 ，再Enter/回车：
Attach成功之后，会打印Arthas LOGO。输入 help 可以获取到更多的帮助信息。

[INFO] Start download arthas from remote server: https://arthas.aliyun.com/download/3.5.2?mirror=center
[INFO] Download arthas success.
[INFO] arthas home: /root/.arthas/lib/3.5.2/arthas
[INFO] Try to attach process 36
[INFO] Attach process 36 success.
[INFO] arthas-client connect 127.0.0.1 3658
  ,---.  ,------. ,--------.,--.  ,--.  ,---.   ,---.                           
 /  O  \ |  .--. ''--.  .--'|  '--'  | /  O  \ '   .-'                          
|  .-.  ||  '--'.'   |  |   |  .--.  ||  .-.  |`.  `-.                          
|  | |  ||  |\  \    |  |   |  |  |  ||  | |  |.-'    |                         
`--' `--'`--' '--'   `--'   `--'  `--'`--' `--'`-----'                          
                                                                                

wiki       https://arthas.aliyun.com/doc                                        
tutorials  https://arthas.aliyun.com/doc/arthas-tutorials.html                  
version    3.5.2                                                                
main_class                                                                      
pid        36                                                                   
time       2021-07-24 03:27:21                                                  

[arthas@36]$

出现**[arthas@36]$**说明arthas在服务上注入成功了。

记得目标进程推出arthas，必须在命令行执行stop命令，否则目标进程还运行了arthas程序。

定位Http问题

Http访问出问题，spring boot使用了servlet，所以通过以下定位：
trace javax.servlet.Servlet * ‘#cost>1000’ -n 1000 > /tmp/servlet.txt

正则匹配日志
\[[0-9]{3,}.

+---[0.002946ms] org.springframework.web.context.request.ServletWebRequest:checkNotModified() #95
+---[0.004987ms] org.springframework.web.servlet.HandlerExecutionChain:applyPreHandle() #986
+---[0.001835ms] org.springframework.web.servlet.HandlerExecutionChain:getHandler() #991
+---[5960.628644ms] org.springframework.web.servlet.HandlerAdapter:handle() #95
+---[0.003077ms] org.springframework.web.context.request.async.WebAsyncManager:isConcurrentHandlingStarted() #993
+---[0.02907ms] org.springframework.web.servlet.DispatcherServlet:applyDefaultViewName() #997
|   `---[0.007616ms] org.springframework.web.servlet.DispatcherServlet:applyDefaultViewName()
+---[0.007406ms] org.springframework.web.servlet.HandlerExecutionChain:applyPostHandle() #998
+---[0.058581ms] org.springframework.web.servlet.DispatcherServlet:processDispatchResult() #1008

主要问题是还是服务处理耗时。

定位健康检查

trace org.springframework.boot.actuate.health.* -n 5000 --skipJDKMethod false > /tmp/actuate.txt

注意不要使用trace org.springframework.boot.actuate.*，否则会引起事故。
一切操作前需要确认VM的内存和限制，否则会引起事故。
退出前记得做清理现场工作，reset/stop否则所有操作将驻留目标进程，将产生一定的性能衰减。
如果可能操作前减少并发流量，已避免生产事故。

我们通过排查，得到以下结果

[3674.863706ms] org.springframework.boot.actuate.health.CompositeHealthIndicator:health()

 +---[min=0.326528ms,max=3673.201185ms,total=3673.967636ms,count=3] org.springframework.boot.actuate.health.HealthIndicator:health() #57
 |   +---[min=0.318738ms,max=0.425684ms,total=0.744422ms,count=2] org.springframework.boot.actuate.health.AbstractHealthIndicator:health()
 |   |   +---[min=0.017501ms,max=0.021212ms,total=0.038713ms,count=2] org.springframework.boot.actuate.health.Health$Builder:<init>() #82
 |   |   +---[min=0.198909ms,max=0.27063ms,total=0.469539ms,count=2] org.springframework.boot.actuate.health.AbstractHealthIndicator:doHealthCheck() #84
 |   |   |   +---[0.258485ms] org.springframework.boot.actuate.system.DiskSpaceHealthIndicator:doHealthCheck()
 |   |   |   `---[0.181693ms] org.springframework.cloud.health.RefreshScopeHealthIndicator:doHealthCheck()
 |   |   `---[min=0.076515ms,max=0.11343ms,total=0.189945ms,count=2] org.springframework.boot.actuate.health.Health$Builder:build() #94
 |   `---[0.111383ms] org.springframework.boot.actuate.health.AbstractReactiveHealthIndicator:health()
 |       +---[0.013442ms] org.springframework.boot.actuate.health.Health$Builder:<init>() #34
 |       +---[0.073209ms] org.springframework.boot.actuate.health.AbstractReactiveHealthIndicator:doHealthCheck() #57
 |       `---[0.003341ms] reactor.core.publisher.Mono:onErrorResume() #57
 +---[min=0.005404ms,max=0.026611ms,total=0.039894ms,count=3] java.util.Map:put() #57

从日志上看做了三个健康检查，但是从堆栈上看只有两次，分别是DiskSpaceHealthIndicator和RefreshScopeHealthIndicator，第三次是redis（Lettuce客户端的并未出现在跟踪），接下来排查具体原因。

org.springframework.boot.actuate.health.CompositeHealthIndicator是健康检查的入口, 查看源码。

	@Override
	public Health health() {
		Map<String, Health> healths = new LinkedHashMap<>();
		for (Map.Entry<String, HealthIndicator> entry : this.indicators.entrySet()) {
			healths.put(entry.getKey(), entry.getValue().health());
		}
		return this.healthAggregator.aggregate(healths);
	}

通过断点观察，发现redis检查实例，如下图所示：
由于HealthIndicatorBeansComposite的实现在对象在org.springframework.boot.actuate.autoconfigure.health包下，所以Arthas的trace没法跟踪到。

我们看下HealthIndicatorBeansComposite的关键实现，通过ReactiveHealthIndicator反射，通过adapt函数将lambda增加到了健康检查列表，所有异步检查都在执行了block等待。

private static class ReactiveHealthIndicators {
        private ReactiveHealthIndicators() {
        }

        public Map<String, HealthIndicator> get(ApplicationContext applicationContext) {
            Map<String, HealthIndicator> indicators = new LinkedHashMap();
            applicationContext.getBeansOfType(ReactiveHealthIndicator.class).forEach((name, indicator) -> {
                HealthIndicator var10000 = (HealthIndicator)indicators.put(name, this.adapt(indicator));
            });
            return indicators;
        }

        private HealthIndicator adapt(ReactiveHealthIndicator indicator) {
            return () -> {
                return (Health)indicator.health().block();
            };
        }
    }

由此Lettuce客户端使用异步ReactiveHealthIndicator异步检查，所有关键在lambda表达式子实现的式阻塞等待方式，代码如下：

() -> {
   return (Health)indicator.health().block();
};

热修复

既然发现有可能式这里阻塞了，怎么验证呢？为了避免重启后无法定位问题，所以采用Arthas进行热修复该问题进行验证。
先来看下效果，如下图所示：
怎么做呢？参考官方文档？这次主要修改org.springframework.boot.actuate.health.CompositeHealthIndicator类进行热修复。

反编译

可以通过 jad 命令来反编译代码，通过–source-only参数可以只打印出在反编译的源代码：

jad --source-only org.springframework.boot.actuate.health.CompositeHealthIndicator > /tmp/CompositeHealthIndicator.java

修改源码

...
public class CompositeHealthIndicator
       implements HealthIndicator {
           private final Map<String, HealthIndicator> indicators;
           private final HealthAggregator healthAggregator;
       
           public Health health() {
               LinkedHashMap<String, Health> healths = new LinkedHashMap<String, Health>();
               for (Map.Entry<String, HealthIndicator> entry : this.indicators.entrySet()) {
                   if (entry.getKey().equals("redis")) continue;
/*68*/             healths.put(entry.getKey(), entry.getValue().health());
               }
/*70*/         return this.healthAggregator.aggregate(healths);
           }
           ...

增加redis检查关闭
if (entry.getKey().equals("redis")) continue;

编译

sc查找加载UserController的ClassLoader

$ sc -d org.springframework.boot.actuate.health.CompositeHealthIndicator  | grep classLoaderHash
 classLoaderHash   <classLoaderHash-id>

也可以通过mc -c /tmp/CompositeHealthIndicator.java -d /tmp，使用-c参数指定ClassLoaderHash:

$ mc -c <classLoaderHash-id> /tmp/CompositeHealthIndicator.java -d /tmp

redefine

再使用redefine命令重新加载新编译好的CompositeHealthIndicator.class：

redefine /tmp/org/springframework/boot/actuate/health/CompositeHealthIndicator.class

$ redefine /tmp/org/springframework/boot/actuate/health/CompositeHealthIndicator.class
redefine success, size: 1

问题定位

通过热修复，关闭对redis的健康检查，我们在线获得了该问题确实可以通过关闭Redis的健康检查来减少该问题，但我们还是需要有工程师思维，这个问题不能放过。

tcpdump

发现问题，我们reset后做tcpdump抓包，进行问题分析。
通过报文我们发现redis是长链接，以下是出问题的报文截图：
正常的包序号是蓝色和红色部分，但是绿色部分出现不同的包需要这时候需要重传，从而导致3s的访问延时，初步判断网络上有丢包的可能导致报文重传，从seq中序号就可以看出来，重传后报文就收到了。

这个问题应该困扰好久了，我相信其他也有。

总结

任何看上去不协调的地方都有问题，只是你目前没有发现，或者选择信忽略。试图证明没有问题很简单，几个正向例子就可以（内心的安慰），但是最困难的事证明有问题（不协调的地方），这些地方需要你花时间去理解，思考，实验，这往往是目前大多数人不愿意投入的地方。

问题解决

最终定位是生产上的Redis其中一个节点开启了持久化（这个问题一开始就排除了），运维关闭该主节点持久化化后，其中一个机房的健康检查交互正常。

参考

Arthas官方文档：https://arthas.aliyun.com/doc/#