异常堆栈信息丢失?到底是怎么回事?
01 即時(shí)編譯優(yōu)化
Java程序在運(yùn)行初期是通過(guò)解釋器來(lái)執(zhí)行,當(dāng)發(fā)現(xiàn)某塊代碼運(yùn)行特別頻繁,就會(huì)將之判定為熱點(diǎn)代碼(Hot Spot Code), 虛擬機(jī)會(huì)將這部分代碼編譯成本地機(jī)器碼,并對(duì)這些代碼進(jìn)行優(yōu)化。這件事就是即時(shí)編譯(Just In Time, JIT)優(yōu)化, 做這件事的就是即時(shí)編譯器。
1.?解釋器與編譯器
目前主流虛擬機(jī)都采用解釋器、編譯器并存的架構(gòu)。
解釋器:程序執(zhí)行初期,解釋器執(zhí)行的方式可以省去編譯過(guò)程,節(jié)省時(shí)間
編譯器:在渡過(guò)初期后,編譯器把更多的代碼編譯成本地代碼,提升執(zhí)行效率,以空間換時(shí)間
因?yàn)榫幾g器存在過(guò)度優(yōu)化,基于假設(shè)優(yōu)化等可能失敗的優(yōu)化結(jié)果,通過(guò)逆優(yōu)化(Deoptimization)的方式,將程序的執(zhí)行主動(dòng)權(quán)從編譯器交給解釋器執(zhí)行??梢园呀忉屍骺闯墒且粋€(gè)保守派,編譯器是一個(gè)激進(jìn)派,在JVM執(zhí)行體系里,兩者相輔相成,互相配合。
1.1 編譯器種類(lèi)
一般虛擬機(jī)都內(nèi)置了兩個(gè)或三個(gè)即時(shí)編譯器,歷史比較久遠(yuǎn)的C1, C2, 以及在JDK10才出現(xiàn)的Graal
C1:客戶端編譯器(Client Complier),執(zhí)行時(shí)間較短,啟動(dòng)程序的時(shí)間較快。在一些物聯(lián)網(wǎng)小型設(shè)備上可指定這種編譯器,通過(guò)-client參數(shù)強(qiáng)制指定
C2:服務(wù)端編譯器(Server Complier),執(zhí)行時(shí)間較長(zhǎng),啟動(dòng)時(shí)間較長(zhǎng)但可編譯高度優(yōu)化的代碼,峰值性能更高??赏ㄟ^(guò)-server參數(shù)強(qiáng)制指定
Graal:是一個(gè)實(shí)驗(yàn)性質(zhì)的即時(shí)編譯器,其最大的特點(diǎn)是該編譯器用Java語(yǔ)言編寫(xiě),更加模塊化,也更容易開(kāi)發(fā)與維護(hù)。充分預(yù)熱后Java代碼編譯成二進(jìn)制碼后其執(zhí)行性能并不亞于由C++編寫(xiě)的C2??梢酝ㄟ^(guò)參數(shù) -XX:+UnlockExperimentalVMOptions -XX:+UseJVMCICompiler 啟用,并替換 C2
1.2 分層編譯優(yōu)化
雖然可以通過(guò)-Xint參數(shù)強(qiáng)制虛擬機(jī)處于"解釋模式"此時(shí)編譯器不工作,可以通過(guò)-Xcomp參數(shù)強(qiáng)制虛擬機(jī)處于"編譯模式"此時(shí)解釋器不工作,可以通過(guò)-client參數(shù)使C2不工作,也可以通過(guò)-server參數(shù)使C1不工作,但是并不推薦這樣做,因?yàn)橛蟹謱泳幾g優(yōu)化這一特性。
編譯器在編譯代碼的時(shí)候會(huì)占用程序運(yùn)行時(shí)間,優(yōu)化程度越高的代碼編譯時(shí)間會(huì)越長(zhǎng),甚至?xí)枰忉屍髫?fù)責(zé)收集程序運(yùn)行監(jiān)控信息提供給編譯器來(lái)編譯優(yōu)化程度更高的代碼。所以為了在更短的時(shí)間內(nèi)編譯優(yōu)化程度更高的代碼,需要編譯器之間的配合,也就是所謂的分層編譯優(yōu)化。一共有五層,分別是:
純解釋執(zhí)行,解釋器不開(kāi)啟收集程序運(yùn)行監(jiān)控信息
使用C1編譯器進(jìn)行簡(jiǎn)單可靠的優(yōu)化,解釋器不開(kāi)啟收集程序運(yùn)行監(jiān)控信息
仍然使用C1編譯器優(yōu)化,但是會(huì)針對(duì)方法調(diào)用次數(shù)和回邊次數(shù)(循環(huán)代碼調(diào)用次數(shù))相關(guān)的統(tǒng)計(jì)
仍然使用C1編譯器優(yōu)化,統(tǒng)計(jì)信息才上一層的基礎(chǔ)上會(huì)加上分支跳轉(zhuǎn)、虛方法調(diào)用等全部統(tǒng)計(jì)信息,解釋器火力全開(kāi)
使用C2編譯器優(yōu)化,相比C1,C2會(huì)開(kāi)啟更多耗時(shí)更長(zhǎng)的優(yōu)化,還會(huì)根據(jù)解釋器提供的程序運(yùn)行信息進(jìn)行一些更為激進(jìn)的優(yōu)化
在開(kāi)啟編譯優(yōu)化后,熱點(diǎn)代碼可能會(huì)被重復(fù)編譯,C1編譯器編譯得更快,C2編譯器編譯質(zhì)量更高,第0層模式解釋器執(zhí)行的時(shí)候也不用收集監(jiān)控信息,第4層模式C2在進(jìn)行耗時(shí)較長(zhǎng)的編譯較為忙碌時(shí)候,C1也能為C2承擔(dān)一部分編譯工作,交互關(guān)系如下圖
common是針對(duì)大部分代碼的編譯情況,trival method針對(duì)執(zhí)行次數(shù)較少的代碼
trival method很少被執(zhí)行所以沒(méi)有被C2編譯的必要,通過(guò)第4層模式的優(yōu)化就足夠了
在C1忙碌的時(shí)候,會(huì)直接由C2編譯;C2忙碌的時(shí)候,在C1編譯的路徑也會(huì)更長(zhǎng)
2. 編譯觸發(fā)條件
上面提到即使編譯是針對(duì)熱點(diǎn)代碼進(jìn)行編譯優(yōu)化,那么什么是熱點(diǎn)代碼?
被多次調(diào)用的方法
被多次執(zhí)行的循環(huán)代碼體
這里的多次如何知道具體有多少次?有兩種方法可以知道
基于采樣的熱點(diǎn)探測(cè)(Sample Based Hot Spot Code Detection): 虛擬機(jī)周期性地檢查各個(gè)線程的調(diào)用棧頂,如果發(fā)現(xiàn)某個(gè)方法經(jīng)常出現(xiàn)在棧頂,那么這個(gè)方法就是熱點(diǎn)方法,這種方法簡(jiǎn)單高效但是精確度不高
基于計(jì)數(shù)器的熱點(diǎn)探測(cè)(Counter Based Hot Spot Code Dection): 虛擬機(jī)為每個(gè)方法建立計(jì)數(shù)器,計(jì)數(shù)器超過(guò)一定閾值就是熱點(diǎn)方法
目前HotSpot虛擬機(jī)使用的是第二種方法,虛擬機(jī)為每個(gè)方法都準(zhǔn)備了兩類(lèi)計(jì)數(shù)器,方法調(diào)用計(jì)數(shù)器以及回邊計(jì)數(shù)器(回邊的意思是在循環(huán)的末尾邊界往回跳轉(zhuǎn),可以理解為循環(huán)代碼的一次執(zhí)行)
講到這里給大家舉一個(gè)工作中經(jīng)常見(jiàn)到的一個(gè)JIT優(yōu)化案例:異常堆棧丟失
02?異常堆棧丟失
1. 問(wèn)題
總所周知在打印Java異常的時(shí)候,會(huì)將其堆棧信息一并輸出,這些堆棧信息非常重要,有助于我們排查問(wèn)題,像這樣
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)但是在最近在觀察系統(tǒng)的線上運(yùn)行日志的時(shí)候,發(fā)現(xiàn)很多不帶堆棧的異常日志,讓人摸不著頭腦到底發(fā)生了什么,像這樣
20:10:50.491?[main]?ERROR?com.yangkw.ErrorTestjava.lang.NullPointerException: null2. 猜想
通過(guò)前面關(guān)于JIT編譯觸發(fā)條件的介紹,可以設(shè)想是拋出異常執(zhí)行太頻繁所以觸發(fā)了JIT優(yōu)化導(dǎo)致,于是我們可以寫(xiě)一個(gè)Demo來(lái)驗(yàn)證,堆棧完整的時(shí)候打印"full trace",堆棧丟失的時(shí)候打印"no trace"
public static void main(String[] args) throws InterruptedException {int count = 0;while (true) {try { count++; //統(tǒng)計(jì)調(diào)用次數(shù) 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(); }下面是執(zhí)行結(jié)果,可以看出程序是在執(zhí)行到8405次(每次執(zhí)行都會(huì)不同)的時(shí)候丟失了堆棧
3. 驗(yàn)證
雖然8405次執(zhí)行的時(shí)候丟失了堆棧,但是并不能說(shuō)明是因?yàn)镴IT優(yōu)化導(dǎo)致的,于是我們可以加上參數(shù)-XX:+PrintCompilation 來(lái)打印即時(shí)編譯情況。
可以看到,在10388次執(zhí)行的時(shí)候是有堆棧信息的,在10389次執(zhí)行的時(shí)候就丟失了堆棧信息,在這中間就發(fā)生了即使編譯優(yōu)化,針對(duì)這一現(xiàn)象官方術(shù)語(yǔ)稱之為"fast throw"可以通過(guò)參數(shù)-XX:-OmitStackTraceInFastThrow關(guān)閉這一優(yōu)化
在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.
堆棧丟失只是表面現(xiàn)象,JIT還對(duì)其做了以下優(yōu)化:
創(chuàng)建需要拋出異常的實(shí)例
清空堆棧信息
將該實(shí)例緩存起來(lái)
之后再需要拋出的時(shí)候,將緩存實(shí)例拋出去
03 總結(jié)
解釋器、C1編譯器、C2編譯器各有優(yōu)劣,合理搭配,干活不累
-XX:-OmitStackTraceInFastThrow 謹(jǐn)慎使用,如果關(guān)閉fast throw的優(yōu)化應(yīng)預(yù)防"日志風(fēng)暴"使磁盤(pán)空間迅速被打滿
做好歷史日志的記錄以及備份,筆者通過(guò)回查歷史日志成功追回了異常的堆棧信息
日照充足的西瓜會(huì)更甜,擁有即時(shí)編譯優(yōu)化會(huì)讓Java程序程序更靈性
有道無(wú)術(shù),術(shù)可成;有術(shù)無(wú)道,止于術(shù)
歡迎大家關(guān)注Java之道公眾號(hào)
好文章,我在看??
總結(jié)
以上是生活随笔為你收集整理的异常堆栈信息丢失?到底是怎么回事?的全部?jī)?nèi)容,希望文章能夠幫你解決所遇到的問(wèn)題。
- 上一篇: 当sql 没有足够的内存执行程序利用命令
- 下一篇: JPA的多表复杂查询