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)退回到解释状态继续执行。
如:
-
static void test(Object input) {
-
if (input == null) {
-
return;
-
}
-
// do something
-
}
如果input一直不为空,执行1W次时,那么上述代码将优化为(类似GCC的 -O2优化算法):
-
static void test(Object input) {
-
// do something
-
}
但是如果之后出现input为空,那么将会触发Uncommon Trap,通过逆优化(Deoptimization)退回到解释状态继续执行。所以触发逆优化是正常的,但是我们的问题是程序一直在做Uncommon Trap,做了很多无用功,这是不正常的。
查阅JVM源码 https://github.com/MuniyappanV/jdk-source-code/blob/master/jdk6u21_src/hotspot/src/share/vm/opto/compile.cpp#L2694,发现有参数可以控制可编译次数:
-
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次数,触发uncommontrap时,且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倍。
火焰图见下图,可以看到耗时与我们Presto遇到的问题非常相似,耗时主要在Deoptimization::uncommon_trap
解决方案:
这个问题是个JVM Bug导致的,既然当达到阈值会触发Deoptimization::Action_none,那么最简单的解决方法是不让他达到阈值就好了。修改JVM参数:
-XX:PerMethodRecompilationCutoff -XX:PerBytecodeRecompilationCutoff
这2个值尽量调大一些,比如2000和500以上。
线上我找了一台机器测试了一周,CPU表现为:
因为这个问题,应该是个JVM Bug,社区找了下关键词,发现JDK 11.0.6 好像解了这个问题,但是这个版本还没有release,无法验证,等版本发布后再验证下。
https://bugs.java.com/bugdatabase/viewbug.do?bugid=8227523
参考链接
-
https://www.slideshare.net/dougqh/jvm-mechanics-when-does-the
-
社区wsmithril网友提供的资料