异常堆栈信息丢失？到底是怎么回事？

01 即时编译优化Java程序在运行初期是通过解释器来执行，当发现某块代码运行特别频繁，就会将之判定为热点代码(Hot Spot Code), 虚拟机会将这部分代码编译成本地机器码，并对...

Hollis Chuang

1200人浏览 · 2020-06-19 09:30:00

Hollis Chuang · 2020-06-19 09:30:00 发布

01 即时编译优化

Java程序在运行初期是通过解释器来执行，当发现某块代码运行特别频繁，就会将之判定为热点代码(Hot Spot Code), 虚拟机会将这部分代码编译成本地机器码，并对这些代码进行优化。这件事就是即时编译(Just In Time, JIT)优化, 做这件事的就是即时编译器。

1. 解释器与编译器

目前主流虚拟机都采用解释器、编译器并存的架构。

解释器：程序执行初期，解释器执行的方式可以省去编译过程，节省时间
编译器：在渡过初期后，编译器把更多的代码编译成本地代码，提升执行效率，以空间换时间

因为编译器存在过度优化，基于假设优化等可能失败的优化结果，通过逆优化(Deoptimization)的方式，将程序的执行主动权从编译器交给解释器执行。可以把解释器看成是一个保守派，编译器是一个激进派，在JVM执行体系里，两者相辅相成，互相配合。

1.1 编译器种类

一般虚拟机都内置了两个或三个即时编译器，历史比较久远的C1, C2, 以及在JDK10才出现的Graal

C1：客户端编译器(Client Complier)，执行时间较短，启动程序的时间较快。在一些物联网小型设备上可指定这种编译器，通过-client参数强制指定
C2：服务端编译器(Server Complier)，执行时间较长，启动时间较长但可编译高度优化的代码，峰值性能更高。可通过-server参数强制指定
Graal：是一个实验性质的即时编译器，其最大的特点是该编译器用Java语言编写，更加模块化，也更容易开发与维护。充分预热后Java代码编译成二进制码后其执行性能并不亚于由C++编写的C2。可以通过参数 -XX:+UnlockExperimentalVMOptions -XX:+UseJVMCICompiler 启用，并替换 C2

1.2 分层编译优化

虽然可以通过-Xint参数强制虚拟机处于"解释模式"此时编译器不工作，可以通过-Xcomp参数强制虚拟机处于"编译模式"此时解释器不工作，可以通过-client参数使C2不工作，也可以通过-server参数使C1不工作，但是并不推荐这样做，因为有分层编译优化这一特性。

编译器在编译代码的时候会占用程序运行时间，优化程度越高的代码编译时间会越长，甚至会需要解释器负责收集程序运行监控信息提供给编译器来编译优化程度更高的代码。所以为了在更短的时间内编译优化程度更高的代码，需要编译器之间的配合，也就是所谓的分层编译优化。一共有五层，分别是：

纯解释执行，解释器不开启收集程序运行监控信息
使用C1编译器进行简单可靠的优化，解释器不开启收集程序运行监控信息
仍然使用C1编译器优化，但是会针对方法调用次数和回边次数(循环代码调用次数)相关的统计
仍然使用C1编译器优化，统计信息才上一层的基础上会加上分支跳转、虚方法调用等全部统计信息，解释器火力全开
使用C2编译器优化，相比C1，C2会开启更多耗时更长的优化，还会根据解释器提供的程序运行信息进行一些更为激进的优化

在开启编译优化后，热点代码可能会被重复编译，C1编译器编译得更快，C2编译器编译质量更高，第0层模式解释器执行的时候也不用收集监控信息，第4层模式C2在进行耗时较长的编译较为忙碌时候，C1也能为C2承担一部分编译工作，交互关系如下图

common是针对大部分代码的编译情况，trival method针对执行次数较少的代码
trival method很少被执行所以没有被C2编译的必要，通过第4层模式的优化就足够了
在C1忙碌的时候，会直接由C2编译；C2忙碌的时候，在C1编译的路径也会更长

2. 编译触发条件

上面提到即使编译是针对热点代码进行编译优化，那么什么是热点代码？

被多次调用的方法
被多次执行的循环代码体

这里的多次如何知道具体有多少次？有两种方法可以知道

基于采样的热点探测(Sample Based Hot Spot Code Detection): 虚拟机周期性地检查各个线程的调用栈顶，如果发现某个方法经常出现在栈顶，那么这个方法就是热点方法，这种方法简单高效但是精确度不高
基于计数器的热点探测(Counter Based Hot Spot Code Dection): 虚拟机为每个方法建立计数器，计数器超过一定阈值就是热点方法

目前HotSpot虚拟机使用的是第二种方法，虚拟机为每个方法都准备了两类计数器，方法调用计数器以及回边计数器(回边的意思是在循环的末尾边界往回跳转，可以理解为循环代码的一次执行)

讲到这里给大家举一个工作中经常见到的一个JIT优化案例：异常堆栈丢失

02 异常堆栈丢失

1. 问题

总所周知在打印Java异常的时候，会将其堆栈信息一并输出，这些堆栈信息非常重要，有助于我们排查问题，像这样

20:10:50.491 [main] ERROR com.yangkw.ErrorTestjava.lang.NullPointerException: nullat com.yangkw.ErrorTest.error(ErrorTest.java:33)  at com.yangkw.ErrorTest.main(ErrorTest.java:19)

但是在最近在观察系统的线上运行日志的时候，发现很多不带堆栈的异常日志，让人摸不着头脑到底发生了什么，像这样

20:10:50.491 [main] ERROR com.yangkw.ErrorTestjava.lang.NullPointerException: null

2. 猜想

通过前面关于JIT编译触发条件的介绍，可以设想是抛出异常执行太频繁所以触发了JIT优化导致，于是我们可以写一个Demo来验证，堆栈完整的时候打印"full trace"，堆栈丢失的时候打印"no trace"

public static void main(String[] args) throws InterruptedException {int count = 0;while (true) {try {                count++; //统计调用次数                error();            } catch (Exception e) {if (e.getStackTrace().length == 0) {                    LOG.error("no trace count:{}", count, e);                    Thread.sleep(1000); //方便观察日志                } else {                    LOG.error("full trace count:{}", count, e);                }            }        }    }private static void error() {        String nullMsg = null;        nullMsg.toString();    }

下面是执行结果，可以看出程序是在执行到8405次(每次执行都会不同)的时候丢失了堆栈

3. 验证

虽然8405次执行的时候丢失了堆栈，但是并不能说明是因为JIT优化导致的，于是我们可以加上参数-XX:+PrintCompilation 来打印即时编译情况。

可以看到，在10388次执行的时候是有堆栈信息的，在10389次执行的时候就丢失了堆栈信息，在这中间就发生了即使编译优化，针对这一现象官方术语称之为"fast throw"可以通过参数-XX:-OmitStackTraceInFastThrow关闭这一优化

在ORACLE官方文档有这么一段描述

The compiler in the server VM now provides correct stack backtraces for all "cold" built-in exceptions. For performance purposes, when such an exception is thrown a few times, the method may be recompiled. After recompilation, the compiler may choose a faster tactic using preallocated exceptions that do not provide a stack trace. To disable completely the use of preallocated exceptions, use this new flag: -XX:-OmitStackTraceInFastThrow.

堆栈丢失只是表面现象，JIT还对其做了以下优化：