Java服务刚启动时，一小波接口超时排查全过程

简介

我们组有一个流量较大的Java服务，每次发代码时，服务都会有一小波接口超时，之前简单分析过，发现这些超时的case仅发生在服务刚启动时，少量请求会耗时好几秒，但之后又马上恢复正常。

问题发生

如下，是我们服务的一次上线，可以看到，上线期间(21:10左右)会有一小波499超时。

而从我们全链路日志平台查看这些超时的调用，会发现外部网络操作(如：rpc调用、查询数据库等)耗时不高，所以耗时来源于执行java代码而非外部调用。

但为啥就刚启动完成那会比较耗时，之后又正常了呢，有点经验的话，肯定会想到这里面估计发生了什么隐式操作，那Java代码执行时会有哪些隐式操作可能导致耗时高呢？
我想到了如下几种情况：

1. 懒加载操作，如连接池初始化、缓存加载？

经过检查，发现这些都已在启动时加载，不会延迟到请求时。

2. 发生了GC？

经过检查，启动时GC正常，耗时不高。

3. JIT即时编译功能导致？

java代码默认是解释执行的，当某些代码被多次执行后，会被JIT编译成原生指令执行，执行性能相应提升，但我通过JVM参数-Xint关闭了JIT后，发现问题依然存在，故排除了此原因。

4. 执行过程中有锁？

经过检查代码，未发现锁的存在。

5. 操作系统相关隐式操作，上下文切换、缺页中断、文件io慢？

经初步检查，CPU、内存、磁盘使用率都正常，这部分深入排查比较费力，且有权限限制，暂先跳过。

那会是什么原因导致的？

问题排查

暂时没啥头绪，我打算先用arthas的profile命令，收集一些CPU火焰图看看。

由于超时仅发生在刚启动完成后的部分请求，之后又恢复正常，故我计划在启动完成后开始收集火焰图，每次收集10s的火焰图，收集3次，然后对比前后的火焰图，看看它们有什么不同，收集脚本如下：

function flamegraph_sample(){
   
    # 不断检测服务直到它启动完成
    while sleep 1; do curl -sS --connect-timeout 3 -m3 http://127.0.0.1:8080/health | grep ok && break; done
    pid=`pgrep -n java`
    for i in