一、问题背景

环境:jdk1.8 + tomcat7

在一次发布时,cpu出现负载过高,其负载突破200%,并且响应时间也大幅度超时。

二、问题分析

【1】发布前做过压测,并没有发现cpu异常升高的现象,所以其可能与生产环境的请求相关。
【2】通过cat观察thread dump虽然发现http线程数有所增加,并且存在block线程数,但是观察锁竞争详情,发现其均是框架代码正常的锁竞争,比如序列化获取时间需要拿到format对象锁,另外也对排除dead lock的可能。

【3】由于测试环境无法复现,所以尝试使用镜像机器,并在惊喜机器中复现cpu上升的问题,由于设计到cpu load的问题,选择使用性能实验室中的cpu 火焰图,观察cpu热点代码。
【4】通过观察火焰图,发现String::equalsIgnoreCase方法位于顶层,且宽度想对较大,也就是说工具在采样cpu执行的代码时,很大一部分都采样到该函数,说明cpu的资源集中在这个函数上。

纵轴表示栈帧深度,横轴表示代码占用CPU/内存的比例,点击可以查看详情。

三、问题排查

【1】根据火焰图分析调用栈,发现String::equalsIgnoreCase代码位于业务代码中的循环中。

// 获取所有的城市
List<CityDataModel> cities = cityService.allCities();
for (CityDataModel city : cities) {
    if (city.getCityCode().equalsIgnoreCase(flight.getDepartCity())) {
        dCountry = city.getCountryCode();
    }
    if (city.getCityCode().equalsIgnoreCase(flight.getArriveCity())) {
        aCountry = city.getCountryCode();
    }
}

【2】通过在测试环境调用该请求,发现其循环的数据时所有的城市列表,而列表的长度可达到12000,而且该循环本身被执行12此,String::equalsIgnoreCase方法执行了20w次,这是一个非常典型的大循环代码,并且通过记录日志发现,在生产中该代码平均每次请求都会调用24w次左右,所有导致cpu资源都集中在该方法上,使得cpu load大幅度提高。

CPU负载定义为在单个时间点使用或等待使用一个内核的进程数。在单核系统,我们的CPU平均负载始终低于0.7。这表明每个需要使用CPU的进程都可以立即使用它,而无需等待。如果CPU平均负载大于1,则表示有进程需要使用CPU,但由于CPU不可用,目前无法使用。在多处理器系统中高于1的平均负载不会成为问题,因为有更多内核可用。

CPU使用率是 CPU处理非空闲任务所花费的时间百分比 。例如单核CPU 1s内非空闲态运行时间为0.8s,那么它的CPU使用率就是80%;双核CPU 1s内非空闲态运行时间分别为0.4s0.6s,那么,总体CPU使用率就是(0.4s + 0.6s) / (1s * 2) = 50%,其中2表示CPU核数,多核CPU同理。CPU使用率只能在指定的时间间隔内测量。我们可以通过将空闲时间的百分比从100中减去来确定CPU使用率。

CPU loadCPU使用率更多可以参考:CPU使用率和负载

四、问题总结

问题解决方案: 由于代码中大循环非常小号cpu资源,通过分析这里String::equalsIgnoreCase方法的作用在于遍历判断获取数据,优先使用hashmap代替,用空间换时间,经过修复后重新发布,cpu利用率明显下降,恢复正常。

思考总结:
【1】使用循环时需要特别注意大循环,有限使用O(1)hashmap,大循环对于cpu性能的压榨问题表现的淋淋尽致。
【2】镜像机器由于是使用生产流量转发,所以高度贴近生产实际发布,所以每次发布前,先使用镜像机器预发布,可以尽可能的将潜在问题暴露出来,性能实验室中提供了cpu热点,内存分配热点和锁竞争热点的Flamegraph,在预发布中遇到问题时也可以更加直观地帮助解决问题,也不会对实际生产机器造成影响。
【3】此次发布前,虽然在测试环境进行了压测,但是并没有复现问题,分析原因,其与特定的压测请求相关,由于在压测时使用的请求没有经过某些代码分支,使得循环的次数想对较少,使得在测试环境中并没有压测出该问题,在压测时,可以尝试使用不同的请求压测并结合镜像机器的预发布来杜绝这种潜在问题发生。

Logo

助力广东及东莞地区开发者,代码托管、在线学习与竞赛、技术交流与分享、资源共享、职业发展,成为松山湖开发者首选的工作与学习平台

更多推荐