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

文章来源原创   作者:临窗旋墨   发布时间:2023-02-28   阅读:1224   标签:spring 分类:java基础 专题:我读[不懂]源码

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

  1. //------------------------------builtin_throw----------------------------------
  2. void GraphKit::builtin_throw(Deoptimization::DeoptReason reason, Node* arg) {
  3. bool must_throw = true;
  4. ... ...
  5. // 首先判断条件是否满足
  6. // If this particular condition has not yet happened at this
  7. // bytecode, then use the uncommon trap mechanism, and allow for
  8. // a future recompilation if several traps occur here.
  9. // If the throw is hot(表示在代码某个位置重复抛出异常), try to use a more complicated inline mechanism
  10. // which keeps execution inside the compiled code.
  11. bool treat_throw_as_hot = false;
  12. if (ProfileTraps) {
  13. if (too_many_traps(reason)) {
  14. treat_throw_as_hot = true;
  15. }
  16. // (If there is no MDO at all, assume it is early in
  17. // execution, and that any deopts are part of the
  18. // startup transient, and don't need to be remembered.)
  19. // Also, if there is a local exception handler, treat all throws
  20. // as hot if there has been at least one in this method.
  21. if (C->trap_count(reason) != 0
  22. && method()->method_data()->trap_count(reason) != 0
  23. && has_ex_handler()) {
  24. treat_throw_as_hot = true;
  25. }
  26. }
  27. // If this throw happens frequently, an uncommon trap might cause
  28. // a performance pothole. If there is a local exception handler,
  29. // and if this particular bytecode appears to be deoptimizing often,
  30. // let us handle the throw inline, with a preconstructed instance.
  31. // Note: If the deopt count has blown up, the uncommon trap
  32. // runtime is going to flush this nmethod, not matter what.
  33. // 这里要满足两个条件:1.检测到频繁抛出异常,2. OmitStackTraceInFastThrow为true,或StackTraceInThrowable为false
  34. if (treat_throw_as_hot
  35. && (!StackTraceInThrowable || OmitStackTraceInFastThrow)) {
  36. // If the throw is local, we use a pre-existing instance and
  37. // punt on the backtrace. This would lead to a missing backtrace
  38. // (a repeat of 4292742) if the backtrace object is ever asked
  39. // for its backtrace.
  40. // Fixing this remaining case of 4292742 requires some flavor of
  41. // escape analysis. Leave that for the future.
  42. ciInstance* ex_obj = NULL;
  43. switch (reason) {
  44. case Deoptimization::Reason_null_check:
  45. ex_obj = env()->NullPointerException_instance();
  46. break;
  47. case Deoptimization::Reason_div0_check:
  48. ex_obj = env()->ArithmeticException_instance();
  49. break;
  50. case Deoptimization::Reason_range_check:
  51. ex_obj = env()->ArrayIndexOutOfBoundsException_instance();
  52. break;
  53. case Deoptimization::Reason_class_check:
  54. if (java_bc() == Bytecodes::_aastore) {
  55. ex_obj = env()->ArrayStoreException_instance();
  56. } else {
  57. ex_obj = env()->ClassCastException_instance();
  58. }
  59. break;
  60. }
  61. ... ...
  62. }

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

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

  • NullPointerException
  • ArithmeticException
  • ArrayIndexOutOfBoundsException
  • ArrayStoreException
  • ClassCastException

本地代码验证

  1. public class FastThrowTest {
  2. static AtomicInteger number = new AtomicInteger(0);
  3. public static void main(String[] args) {
  4. ExecutorService executorService = Executors.newFixedThreadPool(20);
  5. int[] array = new int[]{};
  6. String str = null;
  7. System.out.println(System.getProperty("OmitStackTraceInFastThrow"));
  8. for (int i = 0; i < Integer.MAX_VALUE; i++) {
  9. executorService.execute(new Runnable() {
  10. @Override
  11. public void run() {
  12. System.out.println(number.incrementAndGet() );
  13. if (number.get() %2 == 0) {
  14. int c = array[3];
  15. }else{
  16. str.length();
  17. }
  18. try {
  19. Thread.sleep(2);
  20. } catch (InterruptedException e) {
  21. e.printStackTrace();
  22. }
  23. }
  24. });
  25. }
  26. }
  27. }

如上,默认情况下运行至大约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调优任重而道远。

参考:


发表评论

目录