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 so
    uncommon_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 fail
    if (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;
    @Override
    public void run() {
        try{
            System.out.println(this.getClass().getSimpleName()+"--"+(++count));
            String str = null;
            // 制造空指针NPE
            System.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.NullPointerException
	at 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.NullPointerException
	at 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.NullPointerException
	at 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.NullPointerException
	at 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.NullPointerException
	at 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.NullPointerException
	at 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.NullPointerException
	at 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.NullPointerException
	at 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.NullPointerException
	at 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.NullPointerException
	at 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.NullPointerException
	at 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.NullPointerException
	at 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.NullPointerException
	at 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