Presto System load过高问题调研

背景:

我们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)退回到解释状态继续执行。

如:

1
2
3
4
5
6
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,发现有参数可以控制可编译次数:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
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

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
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次数时性能表现:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
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倍。

火焰图见下图,可以看到耗时与我们Presto遇到的问题非常相似,耗时主要在Deoptimization::uncommon_trap:

解决方案:

既然当达到阈值会触发Deoptimization::Action_none,那么最简单的解决方法是不让他达到阈值就好了。修改JVM参数:

-XX:PerMethodRecompilationCutoff
-XX:PerBytecodeRecompilationCutoff

这2个值尽量调大一些,比如2000和500以上。

线上我找了一台机器测试了一周,CPU表现为:

因为这个问题,应该是个JVM Bug,社区找了下关键词,发现JDK 11.0.6 好像解了这个问题,但是这个版本还没有release,无法验证,等版本发布后再验证下。

https://bugs.java.com/bugdatabase/view_bug.do?bug_id=8227523

参考链接