性能文章>Json 序列化框架导致 CPU 使用率过高>

Json 序列化框架导致 CPU 使用率过高原创

261603

问题现象:CPU 负载过高

我们线上的 jenkins 系统,时不时会发生 CPU 负载过高的现象。

CPU 负载过高后,SRE 同学会收到电话告警。

在我们的监控系统中,可以看到,某些时候,CPU 的负载确实会很高,如下图:

问题排查

Jenkins 系统本身是一个 Java 程序,应对 Java 程序导致的 CPU 使用率过高这一问题,GitHub 上有现成的解决方案:show-busy-java-threads。

下载链接如下:

  • GitHub:show-busy-java-threads

  • Gitee:show-busiest-java-threads

登录上机器,在 CPU 使用率高时候,执行 show-busy-java-threads 脚本:./show-busy-java-threads

摘选其中的一些输出如下:

The stack of busy(25.0%) thread(20239/0x4f0f) of java process(248927) of user(jenkins):
"Handling GET /job/jenkins-test-job/api/json from 172.168.1.1 : qtp1641808846-3127" #3127 prio=5 os_prio=0 tid=0x00007f7380014000 nid=0x4f0f runnable [0x00007f722c392000]
java.lang.Thread.State: RUNNABLE
at java.util.Arrays.copyOfRange(Arrays.java:3664)
at java.lang.String.<init>(String.java:207)
at java.lang.String.substring(String.java:1933)
at net.sf.json.util.JSONTokener.matches(JSONTokener.java:110)
at net.sf.json.JSONObject._fromJSONTokener(JSONObject.java:912)
at net.sf.json.JSONObject.fromObject(JSONObject.java:156)
at net.sf.json.util.JSONTokener.nextValue(JSONTokener.java:348)
at net.sf.json.JSONArray._fromJSONTokener(JSONArray.java:1131)
at net.sf.json.JSONArray.fromObject(JSONArray.java:125)
at net.sf.json.util.JSONTokener.nextValue(JSONTokener.java:351)
at net.sf.json.JSONObject._fromJSONTokener(JSONObject.java:955)
at net.sf.json.JSONObject.fromObject(JSONObject.java:156)
at net.sf.json.util.JSONTokener.nextValue(JSONTokener.java:348)
at net.sf.json.JSONObject._fromJSONTokener(JSONObject.java:955)
at net.sf.json.JSONObject.fromObject(JSONObject.java:156)
at net.sf.json.util.JSONTokener.nextValue(JSONTokener.java:348)
at net.sf.json.JSONObject._fromJSONTokener(JSONObject.java:955)
at net.sf.json.JSONObject.fromObject(JSONObject.java:156)
at net.sf.json.util.JSONTokener.nextValue(JSONTokener.java:348)
at net.sf.json.JSONObject._fromJSONTokener(JSONObject.java:955)
at net.sf.json.JSONObject._fromString(JSONObject.java:1145)
at net.sf.json.JSONObject.fromObject(JSONObject.java:162)
at net.sf.json.JSONObject.fromObject(JSONObject.java:132)
at sam.Sam.sendRequestReturnJson(Sam.java:517)
at sam.Sam.getPermissionByUser(Sam.java:225)
at sam.Sam.checkUserPermissionLocal(Sam.java:243)
at com.michelin.cio.hudson.plugins.rolestrategy.PermissionCache.getPermissionSam(RoleMap.java:155)
at com.michelin.cio.hudson.plugins.rolestrategy.PermissionCache.getPermission(RoleMap.java:106)
at com.michelin.cio.hudson.plugins.rolestrategy.RoleMap.hasPermission(RoleMap.java:220)
at com.michelin.cio.hudson.plugins.rolestrategy.RoleMap.access$000(RoleMap.java:166)
at com.michelin.cio.hudson.plugins.rolestrategy.RoleMap$AclImpl.hasPermission(RoleMap.java:569)
at hudson.security.SidACL._hasPermission(SidACL.java:70)

从上面的输出可以看到,25.0% 的 CPU 资源在处理 Handling GET /job/jenkins-test-job/api/json from 172.168.1.1 这个请求。

运维同学根据这个 ip ,定位到发起请求的是某同学 A。这个同学在跑一些定时任务,定时拉取 job 的执行结果。

问题是当我直接访问这个接口:/job/jenkins-test-job/api/json 时,返回并不慢,几乎很快就可以返回。问题应该不是这个接口的问题。

我们接着从 ./show-busy-java-threads 输出往下看:看到其中有问题的调用栈:

at net.sf.json.JSONObject.fromObject(JSONObject.java:132)
at sam.Sam.sendRequestReturnJson(Sam.java:517)
at sam.Sam.getPermissionByUser(Sam.java:225)
at sam.Sam.checkUserPermissionLocal(Sam.java:243)

看起来是这个 Sam 校验用户权限导致的 CPU 使用率过高,而接着看上面的代码 net.sf.json.JSONObject.fromObject,这个是在做 json 的反序列化。

通常来说,json 的序列化、反序列化都是比较费 CPU 的,更糟糕的是,这里用到的 json 序列化框架是 net.sf.json,而不是 Java 常用的 jackson 和 gson 等。

直觉告诉我,肯定是这个 net.sf.json 反序列化引起的 CPU 使用率过高问题。

备注:

通过跟之前维护 jenkins 的同学了解到,他们基于 role-strategy 插件,重写了 jenkins 权限验证逻辑,用的就是 Sam 权限。翻看 sam 权限插件的代码,确实有用 net.sf.json 做 json 反序列化。

到这里,定位到大概率是 Sam 权限插件的 net.sf.json 反序列化引起的问题。

问题复现

为了验证这个问题,我们拿到 Sam 权限插件的代码。找到出问题的关键代码:

public void getPermissionByUser(String email) {
JSONObject params = new JSONObject();
params.put("user_email", email);
params.put("subsystem_id", SAM_JENKINS_SUM_SYSTEM_ID);

JSONObject res = sendRequestReturnJson(URL, "GET", params);
if (res.get("success").equals(true)) {
cacheUserPermission(params.getString("user_email"), res.getJSONObject("permission").getJSONObject(email).getJSONObject("SERVICE"));
}
}

public static JSONObject sendRequestReturnJson(String endpoint, String method, JSONObject params) {
if (method.equals("POST")) {
return JSONObject.fromObject(sendPostRequest(endpoint, params));
} else if (method.equals("GET")) {
return JSONObject.fromObject(sendGetRequest(endpoint, params));
}
return new JSONObject();
}

可以看到,这段代码会根据用户邮箱,发送 http 请求调用 Sam 系统,获取用户的权限数据,然后将数据反序列化成 JSONObject,即:JSONObject.fromObject(sendGetRequest(endpoint, params, token))

在本地,通过复现 A 同学的请求,发现这个请求确实比较慢,而且费 CPU。通过 debug 得知,这个用户返回的 json 数据有 1M 左右,json 反序列化 CPU 打满。

而通过其他用户请求,发现处理很快,返回的 json 数据也比较小。

到这里,确认就是 net.sf.json 框架的反序列化性能问题,引起的 CPU 使用率过高。我们需要替换成其他高性能的 json 序列化框架。

备选有:gson、jackson、fastjson等。fastjson 因为经常出安全漏洞,暂不考虑,我们考虑从 gson、jackson 选择一个。

在选定之前,先对 gson、jackson, 的性能做个基准测试,并与 net.sf.json 做对比。

JMH 基准测试 json 框架性能

Json 框架的性能测试,我们选用 JMH 框架。

JMH 框架是 JDK 官方提供的性能基准测试套件,参考:https://github.com/openjdk/jmh

代码如下:

import com.fasterxml.jackson.databind.JsonNode;
import com.fasterxml.jackson.databind.ObjectMapper;
import com.google.gson.Gson;
import com.google.gson.JsonObject;
import net.sf.json.JSONObject;
import org.apache.commons.io.FileUtils;
import org.openjdk.jmh.annotations.Benchmark;
import org.openjdk.jmh.annotations.BenchmarkMode;
import org.openjdk.jmh.annotations.Mode;
import org.openjdk.jmh.annotations.OutputTimeUnit;
import org.openjdk.jmh.annotations.Param;
import org.openjdk.jmh.annotations.Scope;
import org.openjdk.jmh.annotations.Setup;
import org.openjdk.jmh.annotations.State;
import org.openjdk.jmh.results.format.ResultFormatType;
import org.openjdk.jmh.runner.Runner;
import org.openjdk.jmh.runner.RunnerException;
import org.openjdk.jmh.runner.options.Options;
import org.openjdk.jmh.runner.options.OptionsBuilder;
import org.springframework.util.ResourceUtils;

import java.io.File;
import java.io.IOException;
import java.util.concurrent.TimeUnit;

@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.MILLISECONDS)
@State(Scope.Benchmark)
public class JsonBenchmark {

@Param({"10", "100", "500"})
private int length;

private String json;

private String email = "a@123.com";
private String path = "classpath:sam.json";

@Benchmark
public void testGson() throws IOException {
Gson gson = new Gson();
JsonObject root = gson.fromJson(json, JsonObject.class);

if (root.getAsJsonObject("success").getAsBoolean()) {
JsonObject services = root.get("permission").getAsJsonObject()
.get(email).getAsJsonObject()
.get("SERVICE").getAsJsonObject();
System.out.println(services.size());
}
}

@Benchmark
public void testJackson() throws IOException {
ObjectMapper objectMapper = new ObjectMapper();
JsonNode root = objectMapper.readTree(json);

if (root.get("success").asBoolean()) {
JsonNode services = root.get("permission").get(email).get("SERVICE");
System.out.println(services.size());
}
}

@Benchmark
public void testJsonObject() throws IOException {
JSONObject root = JSONObject.fromObject(json);
if (root.get("success").equals(true)) {
JSONObject services = root.getJSONObject("permission").getJSONObject(email).getJSONObject("SERVICE");
System.out.println(services.size());
}
}

@Setup
public void prepare() throws IOException {
File file = ResourceUtils.getFile(path);
json = FileUtils.readFileToString(file);
}

public static void main(String[] args) throws RunnerException {
Options options = new OptionsBuilder()
.include(JsonBenchmark.class.getSimpleName())
.forks(1)
.warmupIterations(5)
.measurementIterations(2)
// .output("/Users/wxweven/Benchmark.log")
.result("result.json")
.resultFormat(ResultFormatType.JSON)
.build();
new Runner(options).run();
}
}

测试的结果如下:

Benchmark                     (length)  Mode  Cnt     Score   Error  Units
JsonBenchmark.testGson 10 avgt 2 7.979 ms/op
JsonBenchmark.testGson 100 avgt 2 8.958 ms/op
JsonBenchmark.testGson 500 avgt 2 9.975 ms/op
JsonBenchmark.testJackson 10 avgt 2 10.393 ms/op
JsonBenchmark.testJackson 100 avgt 2 12.214 ms/op
JsonBenchmark.testJackson 500 avgt 2 10.548 ms/op
JsonBenchmark.testJsonObject 10 avgt 2 1350.788 ms/op
JsonBenchmark.testJsonObject 100 avgt 2 1350.583 ms/op
JsonBenchmark.testJsonObject 500 avgt 2 1381.046 ms/op

可以看到,gson 和 jackson 性能接近,但是 jsonlib 性能就很差,比另外两个慢 100 多倍。综合考虑性能、api 易用性等,选定 gson 作为替代方案。

替换成 gson

将之前的代码替换成 gson,代码如下:

public void getPermissionByUser(String email) {
JSONObject params = new JSONObject();
params.put("user_email", email);
params.put("subsystem_id", SAM_JENKINS_SUM_SYSTEM_ID);

JsonObject res = sendRequestReturnJsonV2(URL, "GET", params);
if (res.get("success").getAsBoolean()) {
cacheUserPermission(params.getString("user_email"), res.getAsJsonObject("permission").getAsJsonObject(email).getAsJsonObject("SERVICE"));
}

}

public static JsonObject sendRequestReturnJsonV2(String endpoint, String method, JSONObject params) throws IOException {
if (method.equals("POST")) {
return GSON.fromJson(sendPostRequest(endpoint, params, token), JsonObject.class);
} else if (method.equals("GET")) {
return GSON.fromJson(sendGetRequest(endpoint, params, token), JsonObject.class);
}

return new JsonObject();
}

重新编译权限插件后上线,再次查看 CPU 负载监控,发现 CPU 负载确实降下来了(05/13晚上 0 点左右上线的)。

再次重新编译,问题得到解决。

结束语

这个问题,前前后后花费了不少时间,也困扰了 DevOps 团队比较久,经过大家的齐心协力,总算是把问题给解决了。

这篇文章也是对之前排查、解决问题的一个总结。同时,也提醒大家,在使用第三方 jar 包的时候,一定要注意该 jar 包有没有性能、安全等问题。如果不确定的话,可以用 JMH 等手段自己测试一下。

 

 

请先登录,感受更多精彩内容
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

记一次 Java 服务性能优化
背景前段时间我们的服务遇到了性能瓶颈,由于前期需求太急没有注意这方面的优化,到了要还技术债的时候就非常痛苦了。在很低的 QPS 压力下服务器 load 就能达到 10-20,CPU 使用率 60% 以
代码优化日记 ——火焰图找问题代码
一、问题背景- 排序服务,用于推荐item分数预测,详细项目背景及排序请求执行逻辑可参考之前的一篇文章 :《[性能优化:线程资源回收](https://heapdump.cn/user/708
再聊 TCP backlog
这篇文章我们以 backlog 参数来深入研究一下建连的过程。通过阅读这篇文章,你会了解到下面这些知识:- backlog、半连接队列、全连接队列是什么- linux 内核是如何计算半连接队列、全连接
学会这个Thread Dump分析工具,让您秒变性能分析大师!
每次分析thread dump,我都会用肉眼扫描这dump中的线程状态,并企图发现可能存在的死锁,十几万行太难了!有时候记不太清楚各种等待、阻塞的原因,我都偷偷打开一篇博客边看边分析,很明显我还没把原
在被线上大量日志输出导致性能瓶颈毒打了很多次之后总结出的经验
由于线上业务量级比较大(日请求上亿,日活用户几十万),同时业务涉及逻辑很复杂,线上日志级别我们采用的是 info 级别,导致线上日志量非常庞大,经常遇到因为日志写入太慢导致的性能瓶颈(各微服务每小时日
收藏:一些比较好的Redis 性能优化思路总结
在一些网络服务的系统中,Redis 的性能,可能是比 MySQL 等硬盘数据库的性能更重要的课题。比如微博,把热点微博[1],最新的用户关系[2],都存储在 Redis 中,大量的查询击中 Redis
记一次线程池调优经历
原文链接:https://www.cnblogs.com/superfj/p/8313469.html作者:Janti 背景最近的一个项目需要用到招标,临时加了给我们的系统增加了一个性能需求,多少呢?
近期业务大量突增微服务性能优化总结-4.增加对于同步微服务的 HTTP 请求等待队列的监控
最近,业务增长的很迅猛,对于我们后台这块也是一个不小的挑战,这次遇到的核心业务接口的性能瓶颈,并不是单独的一个问题导致的,而是几个问题揉在一起:我们解决一个之后,发上线,之后发现还有另一个的性能瓶颈问