Java服务5xx/进程假死排查

YY-帆S

已于 2024-03-24 13:04:54 修改

阅读量938

点赞数 21

分类专栏： Java 文章标签： spring boot

于 2024-03-24 12:30:15 首次发布

本文链接：https://blog.csdn.net/u010365335/article/details/136985461

版权

Java 专栏收录该内容

4 篇文章 0 订阅

订阅专栏

3、优化 logback-sping.xml

2）结论

3）参考文档

一、现象

Java Api服务不定时会有一次短时间的5xx，持续十几秒，随后自愈

1、伴随表现

1）线程数突涨

2）接口耗时上涨

部分接口耗时接口长达十几秒

3）Cpu抑制明显

4）宿主机/data目录使用率降低

二、排查方向

业务代码侧没看出问题，因此针对每一个可能的点进行逐一排查和优化

1、调整pod配置-无效

1）方案

每次出现5xx均伴随着CPU抑制，怀疑短时间内请求QPS暴涨，因此调整pod配置，上调CPU和内存配置，并调整启动参数配置

原JVM参数：

-Djava.net.preferIPv4Stack=true -Dfile.encoding=UTF-8 -server -Xms2000m -Xmx2000m -Xmn1024m -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=512m -XX:SurvivorRatio=8 -XX:+UseConcMarkSweepGC -XX:AutoBoxCacheMax=20000 -XX:-UseCounterDecay -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:+PrintGCApplicationStoppedTime -XX:+PrintPromotionFailure -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=10M -XX:+HeapDumpOnOutOfMemoryError -XX:+DisableExplicitGC

调整后JVM参数：

-Djava.net.preferIPv4Stack=true -Dfile.encoding=UTF-8 -server -Xms4096m -Xmx4096m -Xmn2048m -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=512m -XX:SurvivorRatio=8 -XX:+UseConcMarkSweepGC -XX:AutoBoxCacheMax=20000 -XX:-UseCounterDecay -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:+PrintGCApplicationStoppedTime -XX:+PrintPromotionFailure -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=30 -XX:GCLogFileSize=10M -XX:+HeapDumpOnOutOfMemoryError -XX:+DisableExplicitGC -XX:+PrintClassHistogramAfterFullGC -XX:+PrintClassHistogramBeforeFullGC -XX:+PrintReferenceGC -XX:PrintFLSStatistics=1

-Xms2000m -> -Xms4096m : 上调jvm启动时分配的内存
-Xmx2000m -> -Xmx4096m : 上调jvm运行过程中分配的最大内存
-Xmn1024m -> -Xmn2048m : 上调堆内新生代大小
-XX:NumberOfGCLogFiles=10 -> -XX:NumberOfGCLogFiles=30 : 保留更多的GC文件日志
新增 -XX:+PrintClassHistogramAfterFullGC：full gc后打印类直方图
新增 -XX:+PrintClassHistogramBeforeFullGC：full gc前打印类直方图
新增 -XX:+PrintReferenceGC：打印年轻代各个引用的数量以及时长
新增 -XX:PrintFLSStatistics=1：统计内存分配情况和碎片统计的信息

2）结论

调整后无明显优化，该方向无效

2、去除自研java服务探针-无效

1）方案

公司内部自研了一套服务上报探针，因此前 java探针的时候出现过偶发性接口超时，因此怀疑是java内网探针问题，去掉探针配置后进行尝试

2）结论

调整后无明显优化，该方向无效

3、去掉耗时最高的请求接口-无效

1）方案

观察5xx 数量最多的接口请求情况，发现大部分耗时堵在 /HttpService/ProxyPass，调用解析token协议之间相差数秒，因此前登录协议出现过异常，故怀疑是解析token有异常

分析代码评估对应5xx接口不需要解析token，因此去掉该协议调用进行尝试

2）结论

调整后无明显优化，该方向无效

4、排查入口拦截器-无效

1）方案

观察绝大部分是拦截都在进Controller前阻塞，因此怀疑是Controller前拦截器的问题

找出所有拦截器
debug模式下，通过断点，在spring的bean里找所有拦截器
添加拦截器执行节点上报
目的：方便观察指定到对应拦截器的时间节点
添加Controller入口Cat上报
目的：方便观察进入Controller时间节点
关掉RequestLogInterceptor 拦截器
观察Cat数据，大部分在RequestLogInterceptor阻塞，怀疑是RequestLogInterceptor导致
关闭 RequestLogInterceptor后进行尝试

2）结论

调整后RequestLogInterceptor 正常关闭，但阻塞依旧存在，阻塞的拦截器不集中，因此该方案无明显优化，该方向无效

5、优化日志logback-有效

1）方案

1、观察Cat线程Dump

发现卡顿时的线程dump，很多线程都在waitting日志写入

2、分析日志输出xml

发现在正式环境下，也会输出控制台日志<appender-ref ref="CONSOLE"/>

核心问题所在

控制台输出日志的方法是ConsoleAppender，该方法输出日志就是同步方式写日志，且源码实现了同步锁，写日志效率低下

private void writeBytes(byte[] byteArray) throws IOException {
    if(byteArray == null || byteArray.length == 0)
        return;
    
    lock.lock();
    try {
        this.outputStream.write(byteArray);
        if (immediateFlush) {
            this.outputStream.flush();
        }
    } finally {
        lock.unlock();
    }
}