007-异常堆栈信息不打印和jvm参数OmitStackTraceInFastThrow

2023-02-28

背景

​ 同事遇到一个问题，就是生产环境在登录的时候遇到500异常，但是后端日志只打印空指针异常，却没有打印堆栈信息，不容易定位到问题代码的位置。

代码定位

客户反应的问题是，其他用户都可以正常登录，只有某两个修改了数据的用户登陆的时候报错。初步怀疑是用户数据问题。

根据代码中相关日志，定位到产生控制正代码的位置为：

if(user.isLocked())

locked字段为Boolean，用户修改的时候，把它置为了空。和客户沟通，把这个字段修改为0，则正常登录。

此处代码重新修改为 if(Boolean.TRUE.equals(user.isLocked()))

为什么log4j不打印堆栈信息呢

​ 这个springMVC项目中使用HandlerExceptionResolver作为全局异常处理器，捕捉了所有异常，写入相关日志，为什么这里只打印message，却没有堆栈信息呢？

​ 本地模拟测试的时候明显是可以打印堆栈的。而且，通过查看logger打印代码，也是正确的日志格式，形如logger.error("message", ex);

难道是jvm故意把这样的堆栈信息给省略了吗？在网上查询了一下，果然存在这种情况：JVM对一些特定的异常类型做了Fast Throw优化，如果检测到在代码里某个位置连续多次抛出同一类型异常的话，C2会决定用Fast Throw方式来抛出异常，而异常Trace即详细的异常栈信息会被清空。

​ 再次查看日志文件，在最初的时候，报错的位置的异常是打印堆栈信息的，在前两日之后才开始省略了堆栈信息。

JVM的OmitStackTraceInFastThrow参数作用与测试

下面的原因分析内容来自简书：异常栈信息不见了之JVM参数OmitStackTraceInFastThrow

JVM中有个参数：OmitStackTraceInFastThrow，字面意思是省略异常栈信息从而快速抛出，那么JVM是如何做到快速抛出的呢？JVM对一些特定的异常类型做了Fast Throw优化，如果检测到在代码里某个位置连续多次抛出同一类型异常的话，C2会决定用Fast Throw方式来抛出异常，而异常Trace即详细的异常栈信息会被清空。这种异常抛出速度非常快，因为不需要在堆里分配内存，也不需要构造完整的异常栈信息。相关的源码的JVM源码的graphKit.cpp文件中，相关源码如下：

//------------------------------builtin_throw----------------------------------
void GraphKit::builtin_throw(Deoptimization::DeoptReason reason, Node* arg) {
  bool must_throw = true;
  ... ...
  // 首先判断条件是否满足
  // 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;
  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.
  // 这里要满足两个条件：1.检测到频繁抛出异常，2. OmitStackTraceInFastThrow为true，或StackTraceInThrowable为false
  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;
    }
    ... ...
}

说明：OmitStackTraceInFastThrow和StackTraceInThrowable都默认为true，所以条件(!StackTraceInThrowable || OmitStackTraceInFastThrow)为true，即JVM默认开启了Fast Throw优化。如果想关闭这个优化，很简单，配置-XX:-OmitStackTraceInFastThrow，StackTraceInThrowable保持默认配置-XX:+OmitStackTraceInFastThrow即可。

另外，根据这段源码的switch .. case ..部分可知，JVM只对几个特定类型异常开启了Fast Throw优化，这些异常包括：

• NullPointerException
• ArithmeticException
• ArrayIndexOutOfBoundsException
• ArrayStoreException
• ClassCastException

本地代码验证

public class FastThrowTest {
    static AtomicInteger number = new AtomicInteger(0);
    public static void main(String[] args) {
        ExecutorService executorService = Executors.newFixedThreadPool(20);
        int[] array = new int[]{};
        String str = null;
        System.out.println(System.getProperty("OmitStackTraceInFastThrow"));
        for (int i = 0; i < Integer.MAX_VALUE; i++) {
            executorService.execute(new Runnable() {
                @Override
                public void run() {
                    System.out.println(number.incrementAndGet() );
                    if (number.get() %2 == 0) {
                       int c =  array[3];
                    }else{
                        str.length();
                    }
                    try {
                        Thread.sleep(2);
                    } catch (InterruptedException e) {
                        e.printStackTrace();
                    }
                }
            });
        }
    }
}

如上，默认情况下运行至大约6000-8000次之后，就不再打印堆栈信息，只会抛出如下异常信息：

Exception in thread “pool-1-thread-7017” java.lang.NullPointerException
Exception in thread “pool-1-thread-6996” java.lang.ArrayIndexOutOfBoundsException

当配置了参数-XX:-OmitStackTraceInFastThrow之后，即使运行到两万多次依然会打印堆栈信息。

至此，问题基本解决，但是JVM调优任重而道远。

参考：

• 异常栈信息不见了之JVM参数OmitStackTraceInFastThrow)

• JVM调优之经验