Java服务刚启动时接口超时排查全过程

 更新时间:2023年07月24日 10:23:18   作者:扣钉日记  
这篇文章主要为大家介绍了Java服务刚启动时,一小波接口超时排查全过程,有需要的朋友可以借鉴参考下,希望能够有所帮助,祝大家多多进步,早日升职加薪

简介

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

问题发生

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

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

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

  • 懒加载操作,如连接池初始化、缓存加载?

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

  • 发生了GC?

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

  • JIT即时编译功能导致?

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

  • 执行过程中有锁?

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

  • 操作系统相关隐式操作,上下文切换、缺页中断、文件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个火焰图如下:

乍一看,火焰图中没有明显的瓶颈点,但经过仔细查看,在第一张火焰图中搜索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:1021:14:18时间段是一次耗时近8s的慢调用,所以我用此条件在jmc里过滤出此case的调用栈数据,如下:

可以发现,确实绝大多数耗时发生在类加载上,类加载之所以慢是因为加载类有锁竞争,而我们接口由于查表较多,确实会触发非常多类的加载,所以问题比较明显。

问题解决

知道原因后,解决起来就简单了,把类提前加载到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);
        }
    }
}

类预加载上线后,后面又进行过多次代码发布,发布过程中几乎不会再产生超时情况,问题确认已解决。

总结

此次问题的排查过程,还是用到了不少排查技巧的,总结一下:

  • 当看起来不应该慢的代码执行慢时,可以想想有哪些可能的隐式操作存在,此次case的隐式操作就是类加载。
  • 当诊断问题没有头绪时,可考虑使用arthas的profile命令来绘制火焰图,看从火焰图中能不能找到线索,尽管不会总是有效。
  • 当从CPU火焰图中看不出明显问题时,可通过对比问题前后的火焰图来找不同点。
  • 理解profile的-e cpu(默认)与-e wall选项的差异,一般-e cpu诊断高cpu问题,而-e wall诊断高耗时问题,但如果是偶尔慢一下,需要case by case分析,可考虑使用jfr格式保存诊断数据。

以上就是Java服务刚启动时接口超时排查全过程的详细内容,更多关于Java服务启动接口超时排查的资料请关注脚本之家其它相关文章!

相关文章

  • 使用Spring开启@Async异步方式(javaconfig配置)

    使用Spring开启@Async异步方式(javaconfig配置)

    这篇文章主要介绍了使用Spring开启@Async异步方式(javaconfig配置),具有很好的参考价值,希望对大家有所帮助。如有错误或未考虑完全的地方,望不吝赐教
    2021-08-08
  • Spring Boot定制type Formatters实例详解

    Spring Boot定制type Formatters实例详解

    在本篇文章里小编给大家整理的是关于Spring Boot定制type Formatters实例知识点,需要的朋友们学习下。
    2019-11-11
  • SpringBoot2.1.3修改tomcat参数支持请求特殊符号问题

    SpringBoot2.1.3修改tomcat参数支持请求特殊符号问题

    最近遇到一个问题,比如GET请求中,key,value中带有特殊符号,请求会报错。接下来通过本文给大家分享解决SpringBoot2.1.3修改tomcat参数支持请求特殊符号 ,需要的朋友可以参考下
    2019-05-05
  • Java在重载中使用Object的问题

    Java在重载中使用Object的问题

    这篇文章主要介绍了Java在重载中使用Object的问题,具有很好的参考价值,希望对大家有所帮助。如有错误或未考虑完全的地方,望不吝赐教
    2022-02-02
  • JAVA | Guava EventBus 使用 发布/订阅模式的步骤

    JAVA | Guava EventBus 使用 发布/订阅模式的步骤

    这篇文章主要介绍了JAVA | Guava EventBus 使用 发布/订阅模式的步骤,帮助大家更好的理解和学习使用Guava EventBus,感兴趣的朋友可以了解下
    2021-03-03
  • Java自带的加密类MessageDigest类代码示例

    Java自带的加密类MessageDigest类代码示例

    这篇文章主要介绍了Java自带的加密类MessageDigest类代码示例,分享了常见的三种加密方式代码示例,具有一定参考价值,需要的朋友可以了解下。
    2017-11-11
  • 谈谈你可能并不了解的java枚举

    谈谈你可能并不了解的java枚举

    这篇文章主要给大家介绍了一些关于你可能并不了解的java枚举的相关资料,文中通过示例代码介绍的非常详细,对大家的学习或者工作具有一定的参考学习价值,需要的朋友们下面随着小编来一起学习学习吧
    2020-09-09
  • SpringBoot整合Elasticsearch实现索引和文档的操作方法

    SpringBoot整合Elasticsearch实现索引和文档的操作方法

    Elasticsearch 基于 Apache Lucene 构建,采用 Java 编写,并使用 Lucene 构建索引、提供搜索功能,本文分步骤通过综合案例给大家分享SpringBoot整合Elasticsearch的相关知识,感兴趣的朋友跟随小编一起看看吧
    2021-05-05
  • 基于java使用钉钉机器人向钉钉群推送消息

    基于java使用钉钉机器人向钉钉群推送消息

    这篇文章主要介绍了基于java使用钉钉机器人向钉钉群推送消息,文中通过示例代码介绍的非常详细,对大家的学习或者工作具有一定的参考学习价值,需要的朋友可以参考下
    2019-11-11
  • Java实现Socket的TCP传输实例

    Java实现Socket的TCP传输实例

    这篇文章主要介绍了Java实现Socket的TCP传输,实例分析了java通过socket实现TCP传输的相关技巧,需要的朋友可以参考下
    2015-05-05

最新评论