【JVM】JVM异常不打印堆栈信息 [ -XX:-OmitStackTraceInFastThrow ]

一、背景

生产环境日志突然膨胀到100G+, 为了定位问题,所以截取了部分报错日志,
问题是 堆栈信息呢? 哪里报的NPE在哪???

信息如下:

[ERROR] 2020-12-09 09:41:50.053  - [taskAppId=TASK-1919-33805-97659]:[156] - wait task quit failed, instance id:33805, task id:97659
[ERROR] 2020-12-09 09:41:50.053  - [taskAppId=TASK-1919-34759-100696]:[154] - exception
java.lang.NullPointerException: null
[ERROR] 2020-12-09 09:41:50.053  - [taskAppId=TASK-1919-34759-100696]:[156] - wait task quit failed, instance id:34759, task id:100696
[ERROR] 2020-12-09 09:41:50.059  - [taskAppId=TASK-1917-7841-18206]:[154] - exception
java.lang.NullPointerException: null
[ERROR] 2020-12-09 09:41:50.059  - [taskAppId=TASK-1917-7841-18206]:[156] - wait task quit failed, instance id:7841, task id:18206
[ERROR] 2020-12-09 09:41:50.059  - [taskAppId=TASK-1919-33805-97659]:[154] - exception
java.lang.NullPointerException: null

二、原因

JVM中有个参数：OmitStackTraceInFastThrow，省略异常栈信息从而快速抛出异常.

JVM对一些特定的异常类型做了Fast Throw优化，如果检测到在代码里某个位置连续多次抛出同一类型异常的话，C2会决定用FastThrow方式来抛出异常，而异常Trace即详细的异常栈信息会被清空。这种异常抛出速度非常快，因为不需要在堆里分配内存，也不需要构造完整的异常栈信息。

如果禁用则使用下面的命令:

 -XX:-OmitStackTraceInFastThrow

JVM源码:

//------------------------------builtin_throw----------------------------------
void GraphKit::builtin_throw(Deoptimization::DeoptReason reason, Node* arg) {bool must_throw = true;if (env()->jvmti_can_post_on_exceptions()) {// check if we must post exception events, take uncommon trap if souncommon_trap_if_should_post_on_exceptions(reason, must_throw);// here if should_post_on_exceptions is false// continue on with the normal codegen}// // If this particular condition has not yet happened at this// bytecode, then use the uncommon trap mechanism, and allow for// a future recompilation if several traps occur here.// If the throw is hot, try to use a more complicated inline mechanism// which keeps execution inside the compiled code.bool treat_throw_as_hot = false;ciMethodData* md = method()->method_data();if (ProfileTraps) {if (too_many_traps(reason)) {treat_throw_as_hot = true;}// (If there is no MDO at all, assume it is early in// execution, and that any deopts are part of the// startup transient, and don't need to be remembered.)// Also, if there is a local exception handler, treat all throws// as hot if there has been at least one in this method.if (C->trap_count(reason) != 0&& method()->method_data()->trap_count(reason) != 0&& has_ex_handler()) {treat_throw_as_hot = true;}}// If this throw happens frequently, an uncommon trap might cause// a performance pothole.  If there is a local exception handler,// and if this particular bytecode appears to be deoptimizing often,// let us handle the throw inline, with a preconstructed instance.// Note:   If the deopt count has blown up, the uncommon trap// runtime is going to flush this nmethod, not matter what.if (treat_throw_as_hot&& (!StackTraceInThrowable || OmitStackTraceInFastThrow)) {// If the throw is local, we use a pre-existing instance and// punt on the backtrace.  This would lead to a missing backtrace// (a repeat of 4292742) if the backtrace object is ever asked// for its backtrace.// Fixing this remaining case of 4292742 requires some flavor of// escape analysis.  Leave that for the future.ciInstance* ex_obj = NULL;switch (reason) {case Deoptimization::Reason_null_check:ex_obj = env()->NullPointerException_instance();break;case Deoptimization::Reason_div0_check:ex_obj = env()->ArithmeticException_instance();break;case Deoptimization::Reason_range_check:ex_obj = env()->ArrayIndexOutOfBoundsException_instance();break;case Deoptimization::Reason_class_check:if (java_bc() == Bytecodes::_aastore) {ex_obj = env()->ArrayStoreException_instance();} else {ex_obj = env()->ClassCastException_instance();}break;}if (failing()) { stop(); return; }  // exception allocation might failif (ex_obj != NULL) {// Cheat with a preallocated exception object.if (C->log() != NULL)C->log()->elem("hot_throw preallocated='1' reason='%s'",Deoptimization::trap_reason_name(reason));const TypeInstPtr* ex_con  = TypeInstPtr::make(ex_obj);Node*              ex_node = _gvn.transform( ConNode::make(C, ex_con) );// Clear the detail message of the preallocated exception object.// Weblogic sometimes mutates the detail message of exceptions// using reflection.int offset = java_lang_Throwable::get_detailMessage_offset();const TypePtr* adr_typ = ex_con->add_offset(offset);Node *adr = basic_plus_adr(ex_node, ex_node, offset);const TypeOopPtr* val_type = TypeOopPtr::make_from_klass(env()->String_klass());// Conservatively release stores of object references.Node *store = store_oop_to_object(control(), ex_node, adr, adr_typ, null(), val_type, T_OBJECT, MemNode::release);add_exception_state(make_exception_state(ex_node));return;}}// %%% Maybe add entry to OptoRuntime which directly throws the exc.?// It won't be much cheaper than bailing to the interp., since we'll// have to pass up all the debug-info, and the runtime will have to// create the stack trace.// Usual case:  Bail to interpreter.// Reserve the right to recompile if we haven't seen anything yet.assert(!Deoptimization::reason_is_speculate(reason), "unsupported");Deoptimization::DeoptAction action = Deoptimization::Action_maybe_recompile;if (treat_throw_as_hot&& (method()->method_data()->trap_recompiled_at(bci(), NULL)|| C->too_many_traps(reason))) {// We cannot afford to take more traps here.  Suffer in the interpreter.if (C->log() != NULL)C->log()->elem("hot_throw preallocated='0' reason='%s' mcount='%d'",Deoptimization::trap_reason_name(reason),C->trap_count(reason));action = Deoptimization::Action_none;}// "must_throw" prunes the JVM state to include only the stack, if there// are no local exception handlers.  This should cut down on register// allocation time and code size, by drastically reducing the number// of in-edges on the call to the uncommon trap.uncommon_trap(reason, action, (ciKlass*)NULL, (char*)NULL, must_throw);
}

三、 代码验证

测试代码:

import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;public class OmitStackTraceInFastThrowTest {public static void main(String[] args) throws InterruptedException {NPEThread npeThread = new NPEThread();ExecutorService executorService = Executors.newFixedThreadPool(20);for (int i=0; i<Integer.MAX_VALUE; i++) {executorService.execute(npeThread);// 稍微sleep一下, 是为了不要让异常抛出太快, 导致控制台输出太快, 把有异常栈信息冲掉, 只留下fast throw方式抛出的异常Thread.sleep(2);}}
}
class NPEThread extends Thread {private static int count = 0;@Overridepublic void run() {try{System.out.println(this.getClass().getSimpleName()+"--"+(++count));String str = null;// 制造空指针NPESystem.out.println(str.length());}catch (Throwable e){e.printStackTrace();}}
}

运行时间长之后,不再打印堆栈信息,日志如下:

NPEThread--467
NPEThread--468
NPEThread--469
NPEThread--470
NPEThread--471
NPEThread--472
NPEThread--473
NPEThread--474
NPEThread--475
NPEThread--476
NPEThread--477
java.lang.NullPointerExceptionat org.apache.dolphinscheduler.api.utils.NPEThread.run(OmitStackTraceInFastThrowTest.java:28)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)
java.lang.NullPointerExceptionat org.apache.dolphinscheduler.api.utils.NPEThread.run(OmitStackTraceInFastThrowTest.java:28)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)
java.lang.NullPointerExceptionat org.apache.dolphinscheduler.api.utils.NPEThread.run(OmitStackTraceInFastThrowTest.java:28)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)
java.lang.NullPointerExceptionat org.apache.dolphinscheduler.api.utils.NPEThread.run(OmitStackTraceInFastThrowTest.java:28)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)
java.lang.NullPointerExceptionat org.apache.dolphinscheduler.api.utils.NPEThread.run(OmitStackTraceInFastThrowTest.java:28)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)
java.lang.NullPointerExceptionat org.apache.dolphinscheduler.api.utils.NPEThread.run(OmitStackTraceInFastThrowTest.java:28)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)
java.lang.NullPointerExceptionat org.apache.dolphinscheduler.api.utils.NPEThread.run(OmitStackTraceInFastThrowTest.java:28)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)
java.lang.NullPointerExceptionat org.apache.dolphinscheduler.api.utils.NPEThread.run(OmitStackTraceInFastThrowTest.java:28)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)
java.lang.NullPointerExceptionat org.apache.dolphinscheduler.api.utils.NPEThread.run(OmitStackTraceInFastThrowTest.java:28)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)
java.lang.NullPointerExceptionat org.apache.dolphinscheduler.api.utils.NPEThread.run(OmitStackTraceInFastThrowTest.java:28)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)
java.lang.NullPointerExceptionat org.apache.dolphinscheduler.api.utils.NPEThread.run(OmitStackTraceInFastThrowTest.java:28)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)
java.lang.NullPointerExceptionat org.apache.dolphinscheduler.api.utils.NPEThread.run(OmitStackTraceInFastThrowTest.java:28)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)
java.lang.NullPointerExceptionat org.apache.dolphinscheduler.api.utils.NPEThread.run(OmitStackTraceInFastThrowTest.java:28)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)

运行时间长之后,不再打印堆栈信息,日志如下:

NPEThread--9030
NPEThread--9031
NPEThread--9032
NPEThread--9033
NPEThread--9034
NPEThread--9035
NPEThread--9036
NPEThread--9037
NPEThread--9038
NPEThread--9039
NPEThread--9040
NPEThread--9041
java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException
java.lang.NullPointerException