记一次Presto Worker OOM的查找过程

背景

最近Presto集群又上线了几个新业务，伴之而来的是OOM很频繁，且发生时间多在早晨8点左右，线上稳定性是高优需要解决的，所以查找了下导致Presto集群OOM的原因，发现了一些问题，这里抛砖引玉下，可能其他使用Presto的用户也会遇到类似的问题。

排查过程

我给一些业务划分了不同的label，这里说明下我们把Presto引擎改进了下，可以动态将机器划分不同的label，这样SQL查询时候指定不同的label，SQL调度时只根据指定的label查找机器即可。之后发现一个业务方的SQL会导致集群OOM。具体表现为，多次Full GC，之后OOM，看GC日志第一感觉应该是有内存泄露。

我通过审计日志（之前通过event-listener实现了个日志审计模块）拿到OOM时2K左右条SQL，发现SQL都是简单的SQL，类似这种：

1
2
SELECT * FROM table WHERE year='2020' AND month='06' AND day='01' LIMIT 10;

根据SQL，我猜测可能以下2种原因导致了OOM：

  • 查询的表存在Hive视图（我让Presto支持了Hive视图）
  • 异常SQL触发了内存泄露

因为这个业务方的SQL都是小查询，90时间也就1S样子，所以懒得推测原因了，直接把SQL拿到，二分法测试环境跑一遍SQL，通过jstat -gcutil查看GC情况，Old区飙升的会认为存在潜在问题，最终定位了6个表有问题，并且在查询这些表SQL时，Old区疯涨，然后Full GC，连续多次Full GC后OOM。

show create table 查看下表字段信息，70-100个左右字段，但惊奇的发现这几个表都是ORC格式，所以OOM与ORC有关系吗？

那通过orcdump查看下这些orc的元信息吧，命令：

1
2
./bin/hive --orcfiledump hdfs://localhost:9000/user/hive/warehouse/orc/000000_0

惊奇的发现这个ORC文件竟然有2W+个Stripe Statistics，猜测是Stripe Statistics太大导致的问题，如下图所示：

第一反应，是不是用户生成orc参数配置错了，比如stripe的大小设置过小，但是看了下业务方的生成orc的参数，属于正常的，如下图：

hadoop du看了下orc文件，发现一个表只有一个orc文件，且竟然大于20GB，根据orc predicate pushdown的先后顺序策略：

  • 文件级别，整个文件级别的统计信息
  • stripe级别，每个stripe每列中的值的统计信息
  • 行级别 (行组)，stripe中每组10000行（默认值）的每列值的统计信息

那文件的大小应该会影响stripe的大小，于是让业务方将repartition改为10，即生成10个文件，测试发现查询小于1S，且无OOM。

验证成功，即Orc Stripe Statistics太大导致的问题。那为什么Stripe Statistics太大会导致Presto OOM呢？

我们测试环境查询一个有问题的SQL，然后perf下，看下火山图，看下当时Presto当时都在做什么，如下图所示：

发现大约70%的CPU都用于GC，剩下的都在执行SQL计算。我们生成一份CPU采样，看下执行SQL计算时主要做什么，如下图：

根据上图可以看到每个Driver对应的split都在读取Stripe Statistics，我们的猜测是符合预期的，所以原因就明朗了：

业务方使用spark产出orc文件，其repartition设置为1，就会产生一个大于20+G的orc文件，导致stripe个数太多，比如产生2W个stripe（有些表orcdump都不成功，stripe statistics太大了，无法dump，远超2W个），假如表有75个字段，那就会产生2W * 75 个实例，如果presto再划分多个split，比如100，那就是100 * 2W * 75 个instance，因为这个内存是untracked memory，无法使用Presto的OOM Killer逻辑，如果机器内存比较小，那可能2个sql就导致oom了。

引擎改进

我们通知了业务方如果ORC文件太大，将ORC拆分为多个文件，但是可能业务方比较多，下次依然遇到类似的问题，所以引擎需要改进下，尽量让这种不符合预期的SQL直接报错。我们知道ORC使用Protocol buffers来定义一个orc file中元数据的结构，PB报文是限制大小的，网上搜索了下是64MB，但是为什么Presto依然能查询报文超过64MB的ORC文件？研究了下，发现CodedInputStream有个setSizeLimit接口可以限制PB报文的大小，我将其改为64MB，发现有问题的SQL将会查询失败，符合预期。

但是我发现一个问题，当报文超过64M，SQL查询失败后，worker old区依然快满了，我jmap触发了full gc，old区没有任何变化，说明有类似内存泄露的问题，但是过了15分钟后，old区恢复正常，我们知道task info会在内存里保留15分钟，难道与这个有关？于是我dump了份内存，使用MAT分析了下。

如下图所示，发现Stripe Statistics依然在内存中：

看下哪里引用了这些类，导致无法被内存释放，如下图所示：

这样就明白了，读取ORC文件失败时候，每个split都抛出了异常，然后异常信息扔入一个链表里，每个异常信息竟然引用了Orc Statistics信息。既然原因明了了，我们将异常信息替换下，这样就避免了Stripe Statistics信息被引用导致无法被释放，简单修改下代码测试下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
@Override
public Metadata readMetadata(HiveWriterVersion hiveWriterVersion, InputStream inputStream)
       throws IOException
{
    CodedInputStream input = CodedInputStream.newInstance(inputStream);
    input.setSizeLimit(PROTOBUF_MESSAGE_MAX_LIMIT); //通过配置修改为可更改，默认为64MB
    OrcProto.Metadata metadata;
    try {
        metadata = OrcProto.Metadata.parseFrom(input);
    }
    catch (IOException e) {
        throw new PrestoException(NOT_SUPPORTED, "read orc proto failed, may be the orc file statistic is too large");
    }
    return new Metadata(toStripeStatistics(hiveWriterVersion, metadata.getStripeStatsList()));
}

之后测试，查询超过64MB报文的ORC文件，查询失败，无内存泄露产生，世界终于清净了。

目录

  1. 1. 背景
  2. 2. 排查过程
  3. 3. 引擎改进