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

原创 临窗旋墨 2023-02-28 阅读:4729 分类: java后端 专题: 非专题 标签: jvm

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文件中,相关源码如下:

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;
    }
    ... ...
}

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

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

  • NullPointerException
  • ArithmeticException
  • ArrayIndexOutOfBoundsException
  • ArrayStoreException
  • ClassCastException

本地代码验证

JAVA 复制代码
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调优任重而道远。

参考:

评论区

avatar
未登录

暂无评论,来发表第一条评论吧~