原创：扣钉日记（微信公众号ID：codelogs），欢迎共享，非公众号转载保存此声明。

简介

咱们组有一个流量较大的Java服务，每次发代码时，服务都会有一小波接口超时，之前简略剖析过，发现这些超时的case仅产生在服务刚发动时，少数恳求会耗时好几秒，但之后又立刻康复正常。

问题产生

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

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

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

但为啥就刚发动完结那会比较耗时，之后又正常了呢，有点经历的话，肯定会想到这里边估计产生了什么隐式操作，那Java代码履行时会有哪些隐式操作或许导致耗时高呢？ 我想到了如下几种状况：

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

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

  1. 产生了GC？

经过查看，发动时GC正常，耗时不高。

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

java代码默许是解说履行的，当某些代码被屡次履行后，会被JIT编译成原生指令履行，履行功能相应提高，但我经过JVM参数-Xint关闭了JIT后，发现问题仍然存在，故排除了此原因。

  1. 履行进程中有锁？

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

  1. 操作系统相关隐式操作，上下文切换、缺页中止、文件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 {1..3}; do
        java -jar arthas-boot.jar -c "profiler start --alluser" "$pid";
        sleep 10s;
        java -jar arthas-boot.jar -c "profiler stop --file /tmp/flamegraph_cpu_%t.html " "$pid";
    done
    java -jar arthas-boot.jar -c "stop" "$pid";
}

生成的前2个火焰图如下：

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

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

乍一看，火焰图中没有显着的瓶颈点，但经过细心查看，在第一张火焰图中查找ClassLoader，能够搜到不少类加载操作(红色部分)，而第二张则基本没有！

莫非是类加载导致的？现在我有80%决心置疑就是它导致的，但类加载有那么慢？

为此，我方案运用profile命令的-e wall形式搜集刚发动完结时的调用栈，并运用jfr格局保存数据，其中wall形式合适确诊高耗时问题，而jfr格局数据会保存时间戳与线程名称，合适case by case剖析，命令如下：

profiler start -e wall --file /tmp/result.jfr

搜集到jfr文件后，运用jmc东西翻开，然后我在日志平台上找到一个慢调用日志，它显现http-nio-8080-exec-28线程在21:14:10到21:14:18时间段是一次耗时近8s的慢调用，所以我用此条件在jmc里过滤出此case的调用栈数据，如下：

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

能够发现，的确绝大多数耗时产生在类加载上，类加载之所以慢是因为加载类有锁竞争，而咱们接口因为查表较多，的确会触发十分多类的加载，所以问题比较显着。

问题处理

知道原因后，处理起来就简略了，把类提早加载到JVM即可，为了简略，我直接运用了spring中的东西方法，如下：

private static final String[] CLASS_PREFIX_ARR = new String[] {
                "org.apache", "com.thoughtworks", "io.netty", "com.google", "io.grpc",
                "com.alibaba", "org.springframework", "cn.hutool", "com.fasterxml", "org.hibernate", 
                "io.opencensus", "org.redisson", "io.micrometer", "io.prometheus",
        };
PathMatchingResourcePatternResolver resolver = new PathMatchingResourcePatternResolver();
for (String classPrefix : CLASS_PREFIX_ARR) {
    Resource[] resources;
    try {
        resources = resolver.getResources(
                "classpath*:" + StringUtils.replaceChars(classPrefix, '.', '/') + "/**/*.class");
    } catch (IOException e) {
        ExceptionUtils.rethrow(e);
        return;
    }
    for (Resource resource : resources) {
        String className = null;
        try (InputStream is = resource.getInputStream()) {
            ClassReader cr = new ClassReader(is);
            className = StringUtils.replaceChars(cr.getClassName(), '/', '.');
            Class<?> clz = Class.forName(className);
            log.info("preLoadClass success: " + className + ", classLoader: " + clz.getClassLoader());
        } catch (Throwable e) { 
            log.warn("preLoadClass failed: " + className);
        }
    }
}

类预加载上线后，后面又进行过屡次代码发布，发布进程中简直不会再产生超时状况，问题确认已处理。

总结

此次问题的排查进程，仍是用到了不少排查技巧的，总结一下：

  1. 当看起来不应该慢的代码履行慢时，能够想想有哪些或许的隐式操作存在，此次case的隐式操作就是类加载。
  2. 当确诊问题没有条理时，可考虑运用arthas的profile命令来绘制火焰图，看从火焰图中能不能找到线索，虽然不会总是有效。
  3. 当从CPU火焰图中看不出显着问题时，可经过比照问题前后的火焰图来找不同点。
  4. 了解profile的-e cpu(默许)与-e wall选项的差异，一般-e cpu确诊高cpu问题，而-e wall确诊高耗时问题，但如果是偶然慢一下，需要case by case剖析，可考虑运用jfr格局保存确诊数据。