org.apache.thrift导致的OOM

1. 背景

昨日开始压测某微服务，但是发现了一个很奇怪的OOM: java heap space

• 通过压测平台压测必现，即使QPS=1时也必现
• 手动触发无法重现
• 发生OOM时，GC日志显示java heap并未全部占用，但gc触发原因是GC (Allocation Failure)
• 除了OOM日志，没有其他任何拦截器日志和业务日志

虽然已经在生产环境见过很多种OOM，但这类奇怪的OOM还是第一次见到。

2. 分析过程

2.1 Java Dump

分析OOM第一步通常就是查看dump文件，但是由于压测环境隔离等原因，至今无法拿到dump文件，先跳过这一步。

2.2 源码

查看错误日志，发现OOM每次都出现在TBinaryProtocol类readStringBody方法的同一行，代码如下：

  public String readStringBody(int size) throws TException {
    try {
      // OOM每次都发生在下行
      byte[] buf = new byte[size];
      trans_.readAll(buf, 0, size);
      return new String(buf, "UTF-8");
    } catch (UnsupportedEncodingException uex) {
      throw new TException("JVM DOES NOT SUPPORT UTF-8");
    }
  }

很明显，OOM是由于反序列化字符串时创建了一个大数组导致的。

2.3 验证猜想

修改配置文件添加thrift.server.protocol.stringLengthLimit = 1048576 1MB，重新发布后。触发压测脚本，错误日志变成了：

org.apache.thrift.protocol.TProtocolException: String length exceeded max allowed: 1347375956; stringlength limit: 1048576
at org.apache.thrift.protocol.TBinaryProtocol.readMessageBegin(TBinaryProtocol.java:230)
at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:27)
at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:286)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Thrift框架试图new一个1347375956长度的byte数组，导致OOM。

3. 原理分析

3.1 Thrift Binary序列化规范

由上表可知，string类型占用字节数为4+N，前4位无符号标识字符串长度，反序列化时，会根据该值分配byte数组。

4. 引用

Thrift序列化协议浅析