性能告警惊四座 神器出手伏恶龙

Hello_world_
402 阅读10分钟

依旧题目顺口溜，准备考研

cbfd292f99be38eec1bd3750c3b5ac656ea468cc.jpg

前言

问题年年有，今年特别多。作为一个刚工作一年多的人，我到底做了什么孽。除了搞定产品提的各种奇怪的需求，还要解决前人留下来的各种问题，我上早八。

该问题实际发生并解决在2025年，年末赶KPI进度没来得及写总结

006BgMUjgy1i6b376m69qj306o06ojre.jpg

事故场景

让我们把时间拉回到问题发生的时间。这个问题发生在2025年12月29日下午3点。

image.png 收到告警后的第一时间，虽然还未排查出是什么原因导致的问题。第一时间对服务进行了扩容操作，避免问题进一步扩散。在完成扩容后，告警随即恢复。在恢复之后本想着可能就是正常的流量波动造成的。在后续时间里，该服务还是会偶尔报出CPU阈值告警。尤其在周末，关于CPU阈值告警更加频繁。CPU使用率最高可达90%以上

image.png

多维度排查

在发生告警后，虽然第一时间采取了处理措施，但是并不知道是什么具体原因导致的CPU突然增高。随即我对该服务进行了多维度的排查。

代码维度

首先，从代码维度分析CPU告警是否是有代码中存在不合理的代码逻辑造成程序出现大量计算逻辑（如：死循环、锁竞争等）。

首先分析代码是否存在死循环。根据告警前发布的代码以及CPU变化曲线分析，如果代码中存在死循环，那么当死循环触发后，CPU利用率将维持在一个较高水平或不断升高，并不会出现CPU利用率降低的情况出现。所以可排查是因代码死循环问题导致的CPU利用率升高。

使用jstack、jstat工具查看对应线程中锁竞争情况

jstack线程分析

# 1. 获取目标Java进程ID 
jps -l 
# 2. 导出线程栈（每隔5秒导出一次，共3次，对比锁状态） 
jstack 线程id > thread-1.log 
sleep 5 
jstack 线程id > thread-2.log 
sleep 5 
jstack 线程id > thread-3.log

jstat锁分析

# 查看锁竞争相关统计（每1秒输出一次，共10次） 
jstat -s 线程id 1000 10

根据jstack、jstat工具的执行结果分析，锁竞争的情况一直存在，而且在持续的正常流量中锁竞争情况相当保持稳定，不会有明显的升高或降低。所以可以排除因为锁竞争导致CPU升高的原因。

流量维度

在排除因为代码维度导致CPU升高的之后，问题排查暂时陷入了停滞。我又重新回顾了该服务最近的变更，发现了可能是导致CPU升高的一个重要原因——流量升高。在发生CPU告警前，该服务接入了一个新的业务，使得核心接口的流量存在明显增大。日均调用量将会增加50W以上。

进一步对流量进行分析发现，该服务调用量增幅已达到40%。此时，似乎已经找到了造成CPU升高的元凶。

s_a4e3b2bc9c4f4da68697fd0071dcbf15.jpg

本该皆大欢喜，但在后续进一步排查时，发现万里长征还远没结束。

在查看接入新业务前，该服务CPU利用率的情况。发现在接入前，该服务CPU利用率虽然没有达到告警阈值，但其CPU利用率也处于较高的水平（最高可达50%）。该CPU利用率结合流量调用以及业务处理并不存在大量计算情况。该调用量不应该存在如此高的CPU利用率。

综合以上信息，我们可以确定流量的增加并不是导致CPU利用率升高的根本原因，但流量增加一定程度导致了CPU利用率的升高。

在进一步分析时，发现2个集群的机器负载均衡相等的情况下CPU利用率有显著差异。联系相关运维人员后，得知集群A的机器性能本就不及集群B，在流量升高的情况下更加显著。

JVM维度

问题排查进度再次陷入了停滞。从代码层面、调用情况都无法排查出导致CPU升高的原因。只能再进一步深挖深层内容。Java程序什么是最深层的技术———JVM。

一想到要从JVM层面排查问题，啊？我吗？

9e2cdc6569bf49239d1ebdf15ff0ed26.webp

虽然内心十分抗拒，但是也不得不干啊。

在JVM层面若存在大量Yong GC、高频JIT编译、锁升级、类加载/卸载发生都会使得CPU利用率升高。在实际生产中更多是由于大量Yong GC导致的。

在查看CPU利用率处于高峰时的JVM运行情况，发现CPU处于某个峰值时，机器对应的JVM同时进行了较高次数的Yong GC。

image.png

从这里可以看出大量的GC操作是会导致CPU升高的。但是本次问题中Young GC和CPU升高的因果关系还需进一步确认。虽然CPU处于峰值时GC次数也处于高峰，但是GC次数处于平稳次数时，CPU利用率虽然没有达到峰值但是也处于较高水平。因此，可以判断出Yong GC次数是进一步导致CPU利用率升高的原因之一，并非导致CPU升高的主要原因。

神器出手

在通过以上维度排查后，虽然找到了一些导致CPU升高的影响原因，但是还是没有排查出CPU升高的根本原因。在此之后，意识到可能是排查工具并不全面。在询问大佬后，了解到一个神器——Arthas。可以更加全面的分析程序运行情况。

0884e955562b16803cfb2aba68bef431432d4570.jpg

在Arthas官网初步了解了其基本用法后，重新开始了CPU问题的排查。

首先，查看了服务运行期间CPU利用率最高的线程。

dashboard        # 实时查看系统运行情况
thread -n 5      # 查看CPU利用率最高的5个线程

image.png

image.png

根据以上情况，基本可以判断是程序中业务代码导致的CPU利用率升高的。

进一步对业务线程进行分析

# 如果发现某个线程CPU过高，查看其堆栈
thread <高CPU线程ID>

# 监控该线程一段时间
thread -i 2000 <线程ID>

# 生成性能报告进一步分析
profiler start
# 等待10秒
profiler stop --format html

在得到业务线程火焰图后，不知好歹的我居然直接对火焰图进行分析，为什么说我不知好歹，请看VCR

image.png 这个是人能分析的吗？果断扔给AI帮我分析，给出一个初步结论。然后我在针对性分析。AI得到的初步结论。

  • 存在大量数据转换操作
  • 高频调用Jackson JSON序列化/反序列化操作

以上2个操作是主要核心影响。在了解到这2个核心原因后，对于火焰图的分析便少了很多繁琐的操作。进一步分析得到，在业务代码中以下这个方法的调用占据CPU时长较高

image.png

在对该方法业务代码分析过程中发现，该方法的业务功能是调用另一个服务的接口获取数据。照常来说这个接口调用属于IO操作，并不会是CPU升高。但是深挖代码后发现，该接口虽然是网络IO操作，但是在得到调用结果（Map）后，会反序列化为特定对象，该操作会使得CPU升高。

此外，在分析火焰图过程中，还发现了一个问题，存在一个工具类的大量调用

image.png

在分析出以上2个代码问题后，开始着手解决这2个代码问题造成的影响。首先想到的就是加缓存，避免重复数据多次运算。但是团队中使用的缓存组件是团队内自建的。而且代码中代码问题1的调用存在部分代码使用了缓存，然而其CPU利用率并没有得到降低。

在进一步对团队中缓存组件代码分析时发现，在缓存组件中存在大量代码问题2的工具类方法调用。该工具类代码大致如下

public static <T> T parseObject(String json, TypeReference<T> type) {
    try {
        ObjectMapper objectMapper = new ObjectMapper();
        configObjectMapper(objectMapper);
        return objectMapper.readValue(json, type);
    } catch (IOException e) {
        throw new FmsFastjsonIOException(e);
    }
}

public static <T> T parseObject(String json, Class<T> clazz) {
    try {
        ObjectMapper objectMapper = new ObjectMapper();
        configObjectMapper(objectMapper);
        return objectMapper.readValue(json, clazz);
    } catch (IOException e) {
        throw new FmsFastjsonIOException(e);
    }
}

public static String toJSONString(Object object) {
        try {
            ObjectMapper objectMapper = new ObjectMapper();
            configObjectMapper(objectMapper);
            return objectMapper.writeValueAsString(object);
        } catch (JsonProcessingException e) {
            throw new FmsFastjsonIOException(e);
        }
    }

以上仅列举了几个方法，该工具类的本质是包装了Jackson序列化/反序列化的代码进行统一调用。以上代码看似符合业务需求。但是存在一个问题，每次方法调用都创建了一个新的ObjectMapper对象。这就使得其底层进行序列化/反序列化的时候，要重新生成对应的序列化器反/序列化器。在流量高峰期间该操作会反复执行就会导致CPU利用率升高。分析到这里，问题就明晰了。上述分析到代码问题1使用了缓存组件，但是缓存组件使用了不合适的序列化/反序列化代码，使得即便使用了缓存组件还是会使CPU利用率升高；代码问题2工具类的使用至今使用了不合适的序列化/反序列化代码，同样也导致了CPU利用率的升高。

分析到这里问题已经明确了，团队中对序列化/反序列化代码的不正确使用导致了服务CPU利用率的升高。

在Jackson底层代码中，序列化/反序列化是采取了缓存策略的。该缓存并非缓存整个对象，而是对象类型及其对应的序列化器/反序列化器。无需再次生成进而降低了CPU利用率

问题解决

在分析出CPU利用率升高的根本问题后，剩下的工作就是解决序列化/反序列化的代码问题。该问题解决起来也十分简单，只需要调用序列化/反序列化操作是，使用同一个ObjectMapper对象即可。

private static volatile ObjectMapper MAPPER;


private static ObjectMapper getStaticMapper() {
    if (MAPPER == null) {
        synchronized (JacksonUtil.class) {
            if (MAPPER == null) {
                ObjectMapper tempMapper = new ObjectMapper();
                // 禁用空Bean序列化时的失败
                tempMapper.configure(SerializationFeature.FAIL_ON_EMPTY_BEANS, false);
                // 忽略null值，只序列化非null字段（可选，根据需求调整）
                tempMapper.setSerializationInclusion(JsonInclude.Include.NON_NULL);
                // 如果需要处理未知属性，可以添加以下配置
                tempMapper.configure(DeserializationFeature.FAIL_ON_UNKNOWN_PROPERTIES, false);
                MAPPER = tempMapper;
            }
        }
    }
    return MAPPER;
}

public static <T> Map<String, T> objectToMap(Object object) {
    try {
        ObjectMapper staticMapper = getStaticMapper();
        String json = staticMapper.writeValueAsString(object);
        return staticMapper.readValue(json, new TypeReference<HashMap<String, T>>() {});
    } catch (IOException e) {
        throw new FmsFastjsonIOException(e);
    }
}

修改完代码后，查看代码运行情况。在相同时间段，该服务CPU利用率得到了大幅降低，降幅达50%以上。

image.png 从结果来看，这次代码优化是成功的

avatar
文章
阅读
粉丝