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

曾经终败给现在 2022-12-27 11:04 306阅读 0赞

# 一. 背景 #

生产环境日志突然膨胀到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