九幺加速玩命中,国产专区欧美天堂,年轻少妇裸体BB

最近，我們升級了 Java 17。后來，我們的 k8s 運(yùn)維團(tuán)隊(duì)為了優(yōu)化我們的應(yīng)用日志采集，將我們所有 pod （你可以理解為一個 Java 微服務(wù)進(jìn)程）的 JVM 日志都統(tǒng)一采集到同一個 AWS 的 EFS 服務(wù)（EFS 是 Elastic File System 的縮寫，彈性塊文件存儲系統(tǒng)，底層是 NFS + S3 對象存儲集群），我們對于 JVM 日志配置包括以下幾個：

GC日志：-Xlog:gc*=debug:file=${LOG_PATH}/gc%t.log:utctime,level,tags:filecount=50,filesize=100M
JIT 編譯日志：-Xlog:jit+compilation=info:file=${LOG_PATH}/jit_compile%t.log:utctime,level,tags:filecount=10,filesize=10M
Safepoint 日志：-Xlog:safepoint=trace:file=${LOG_PATH}/safepoint%t.log:utctime,level,tags:filecount=10,filesize=10M
關(guān)閉堆棧省略：這個只會省略 JDK 內(nèi)部的異常，比如 NullPointerException 這種的：-XX:-OmitStackTraceInFastThrow，我們應(yīng)用已經(jīng)對于大量報錯的時候輸出大量堆棧導(dǎo)致性能壓力的優(yōu)化，

在這樣做之后，我們的應(yīng)用出現(xiàn)這樣一個奇怪的問題，這個問題有三種不同的現(xiàn)象，統(tǒng)一的表現(xiàn)是 處于安全點(diǎn)的時間特別特別長 ：

1.通過 safepoint 日志看出來，等待所有線程進(jìn)入安全點(diǎn)的時間特別長（Reaching safepoint：25s多）

image.png

2.通過 safepoint 日志看出來，還有處于 safepoint 時間過長的，并且原因是 GC（At safepoint: 37s多）

image.png

查看 GC 日志， Heap before GC invocations 與輸出堆結(jié)構(gòu)的日志間隔了很久：

image.png

3.另一種處于 safepoint 時間過長的，原因也是 GC，但是間隔日志的地方不一樣（29s多）

查看 GC 日志，輸出堆結(jié)構(gòu)的日志某些間隔了很久：

image.png

問題定位

首先，Java 應(yīng)用線程整體處于 safepoint，這時候應(yīng)用線程什么都做不了，所以依賴應(yīng)用線程的監(jiān)控即通過 JVM 外部監(jiān)控，例如 spring actuator 暴露的 prometheus 接口，以及 Skywalking 插樁監(jiān)控，是什么都看不到的，只會看到出于安全點(diǎn)時調(diào)用的這些方法時間特別長，但是并不是這些方法真的有瓶。

需要通過 JVM 內(nèi)部線程的監(jiān)控機(jī)制，例如 JVM 日志，以及 JFR（Java Flight Recording）來定位。還有就是通過 async_profiler ( https://github.com/jvm-profiling-tools/async-profiler/ )，因?yàn)槲覀儼l(fā)現(xiàn)，在出問題的時候，進(jìn)程本身的 CPU 占用（注意不是機(jī)器的，是這個進(jìn)程的）也會激增：

image.png

但是非常奇怪的是，通過 async_profiler 查看 CPU 占用，發(fā)現(xiàn)出問題的時間段，除了：

并且在處于安全點(diǎn)的期間，日志也是被中斷了一樣，這是非常少見的，為什么這么說，請看下面分析：

針對現(xiàn)象一，等待所有線程進(jìn)入 safepoint 時間特別長，這個一般會不斷輸出等待哪個線程沒有進(jìn)入安全點(diǎn)的日志，參考 JVM 源碼：

https://github.com/openjdk/jdk/blob/master/src/hotspot/share/runtime/safepoint.cpp

image.png

但是現(xiàn)象一中我們并沒有看到因?yàn)槟膫€線程導(dǎo)致進(jìn)入 safepoint 時間過長。

針對現(xiàn)象二，通過 JFR，也沒看出 GC 的哪個階段耗時很長：

image.png

針對現(xiàn)象三，通過查看 JVM 源碼發(fā)現(xiàn)，輸出這兩個間隔很大的日志的代碼之間，沒有做任何的事情，只是打日志。并且查看所有出異常的時間點(diǎn)， 都是每個小時的 05 分左右 ，詢問運(yùn)維知道在這個時間，會進(jìn)行上一小時日志文件的移出與與 EFS 同步（我們一個小時生成一個日志文件）， 會有大量文件 IO （由于底層使用的是云服務(wù)，也許并不是磁盤，而是 EFS 這種 NFS 或者網(wǎng)絡(luò)對象存儲）。會不會是文件 IO 太大導(dǎo)致 JVM 日志輸出堵住導(dǎo)致 JVM 卡住呢？

為啥 JVM 日志輸出會導(dǎo)致 JVM 所有應(yīng)用線程卡住，假設(shè) JVM 某個線程輸出日志卡住了，倘若沒有處于 safepoint，那么不會卡住所有應(yīng)用線程，只會卡住它自己。但是如果處于 safepoint，所有應(yīng)用線程本身就被暫停了，如果這個時候某個 JVM 線程輸出日志卡住，那么可能造成遲遲不能所有線程進(jìn)入安全點(diǎn)，或者所有處于安全點(diǎn)時間過長。對應(yīng)現(xiàn)象一，某個線程輸出的是 JVM 日志而不是應(yīng)用日志（輸出應(yīng)用日志一般是涉及文件 IO 原生調(diào)用，處于原生調(diào)用直接就算進(jìn)入了安全點(diǎn)，不會有影響，輸出 JVM 日志卡住導(dǎo)致這個線程遲遲沒有進(jìn)入安全點(diǎn)。針對現(xiàn)象二三，都是 GC 線程輸出 JVM 日志卡住導(dǎo)致 GC 遲遲不結(jié)束。

首先通過 JVM 源碼確認(rèn)下 JVM 日志輸出卡住是否會阻塞 JVM。