Presto System load过高问题调研

2019-09-18

背景

我们Presto有个集群，每6.5天会出现System load过高问题，这个集群有个特点，只服务于一个业务方，且SQL基本相似。如图所示：Sys load很高（20-40%），严重影响查询性能。

业务SQL查询时间表现为：

ScanFilterAndProjectOperator（Source Stage）阶段有机器有明显的长尾现象，比如20台机器，正常这个Operator执行时间只需要1S，但是有几台机器会耗时几分钟。而重启服务后，查询恢复正常。

先jstack看下Presto在干啥：

如图所示，Presto通过ScanFilterAndProjectOperator类执行filter过滤，其中这个filter方法是Codegen生成。

pstack查看下线程栈：

看到程序主要CPU浪费在Deoptimization::uncommon_trap里了。为什么呢？再说这个问题之前，我们先说下JIT。

JIT

为了提高热点代码（Hot Spot Code）的执行效率，在运行时，虚拟机将会把这些代码编译成与本地平台相关的机器码，并进行各种层次的优化，完成这个任务的编译器称为即时编译器（JIT）。

“热点代码”两类:

被多次调用的方法
被多次执行的循环体 – 尽管编译动作是由循环体所触发的，但编译器依然会以整个方法（而不是单独的循环体）作为编译对象。
编译器根据概率选择一些大多数时候都能提升运行速度的优化手段，当优化的假设不成立，出现“罕见陷阱”（Uncommon Trap）时可以通过逆优化（Deoptimization）退回到解释状态继续执行。

如：

static void test(Object input) {
    if (input == null) {
	    return;
	}
	// do something
}

如果input一直不为空，执行1W次时，那么上述代码将优化为（类似GCC的 -O2优化算法）：

1
2
3

static void test(Object input) {
// do something
}

但是如果之后出现input为空，那么将会触发Uncommon Trap，通过逆优化（Deoptimization）退回到解释状态继续执行。所以触发逆优化是正常的，但是我们的问题是程序一直在做Uncommon Trap，做了很多无用功，这是不正常的。

查阅JVM源码 compile::too_many_recompiles，发现有参数可以控制可编译次数：

bool Compile::too_many_recompiles(ciMethod* method,
                                  int bci,
                                  Deoptimization::DeoptReason reason) {
 
  // Pick a cutoff point well within PerBytecodeRecompilationCutoff.
  uint bc_cutoff = (uint) PerBytecodeRecompilationCutoff / 8;
  uint m_cutoff  = (uint) PerMethodRecompilationCutoff / 2 + 1;  // not zero
  Deoptimization::DeoptReason per_bc_reason
    = Deoptimization::reason_recorded_per_bytecode_if_any(reason);
 
  if ((per_bc_reason == Deoptimization::Reason_none
       || md->has_trap_at(bci, reason) != 0)
      // The trap frequency measure we care about is the recompile count:
      && md->trap_recompiled_at(bci)
      && md->overflow_recompile_count() >= bc_cutoff) {
    // Do not emit a trap here if it has already caused recompilations.
    // Also, if there are multiple reasons, or if there is no per-BCI record,
    // assume the worst.
    if (log())
      log()->elem("observe trap='%s recompiled' count='%d' recompiles2='%d'",
                  Deoptimization::trap_reason_name(reason),
                  md->trap_count(reason),
                  md->overflow_recompile_count());
    return true;
  } else if (trap_count(reason) != 0
             && decompile_count() >= m_cutoff) {
    // Too many recompiles globally, and we have seen this sort of trap.
    // Use cumulative decompile_count, not just md->decompile_count.
 
    if (log())
      log()->elem("observe trap='%s' count='%d' mcount='%d' decompiles='%d' mdecompiles='%d'",
                  Deoptimization::trap_reason_name(reason),
                  md->trap_count(reason), trap_count(reason),
                  md->decompile_count(), decompile_count());
 
    return true;
  } else {
    // The coast is clear.
    return false;
  }
}

PerMethodRecompilationCutoff 可以控制recompiles次数，触发uncommon_trap时，且too_many_recompiles为true时，其行为为Deoptimization::Action_none。
https://github.com/MuniyappanV/jdk-source-code/blob/master/jdk6u21_src/hotspot/src/share/vm/opto/graphKit.cpp#L1807

void GraphKit::uncommon_trap(int trap_request,
                             ciKlass* klass, const char* comment,
                             bool must_throw,
                             bool keep_exact_action) {
  Deoptimization::DeoptReason reason = Deoptimization::trap_request_reason(trap_request);
  Deoptimization::DeoptAction action = Deoptimization::trap_request_action(trap_request);
 
  switch (action) {
  case Deoptimization::Action_maybe_recompile:
  case Deoptimization::Action_reinterpret:
    // Temporary fix for 6529811 to allow virtual calls to be sure they
    // get the chance to go from mono->bi->mega
    if (!keep_exact_action &&
        Deoptimization::trap_request_index(trap_request) < 0 &&
        too_many_recompiles(reason)) {
      // This BCI is causing too many recompilations.
      action = Deoptimization::Action_none;
      trap_request = Deoptimization::make_trap_request(reason, action);
    } else {
      C->set_trap_can_recompile(true);
    }
    break;
 
  case Deoptimization::Action_make_not_entrant:
    C->set_trap_can_recompile(true);
    break;

我们写个测试程序，测试PerMethodRecompilationCutoff 参数，参数超过recompile次数时性能表现：

public class DeoptimizationTest
{
    private DeoptimizationTest() {}
    static int someComplicatedFunction(double x)
    {
        return (int) (Math.pow(x, x) + Math.log(x) + Math.sqrt(x));
    }
    static void hotMethod(int iteration)
    {
        if (iteration < 20) {
            someComplicatedFunction(1.23);
        }
        else if (iteration < 40) {
            someComplicatedFunction(1.23);
        }
        else if (iteration < 60) {
            someComplicatedFunction(1.23);
        }
        else if (iteration < 80) {
            someComplicatedFunction(1.23);
        }
        else {
            someComplicatedFunction(1.23);
        }
    }
    static void hotMethodWrapper(int iteration)
    {
        int count = 100_000;
        for (int i = 0; i < count; i++) {
            hotMethod(iteration);
        }
    }
    public static void main(String[] args)
    {
        for (int k = 0; k < 100; k++) {
            long start = System.nanoTime();
            hotMethodWrapper(k + 1);
            System.out.println("iteration " + k + ": " + (System.nanoTime() - start) / 1_000_000 + "ms");
        }
    }
}

执行代码：javac DeoptimizationTest.java && java -XX:PerMethodRecompilationCutoff=3 DeoptimizationTest

指定PerMethodRecompilationCutoff为3，意思是PerMethodRecompilationCutoff/2 + 1 = 2，那么第三个分支将触发大量Deoptimization::Action_none操作，如上图所示，发现第59次迭代时，查询变慢了接近600倍。