關於java單線程經常佔用cpu 100%的分析

2021-12-29 OPPO數智技術

背景：這個是在centos7 + lxcfs 和jdk11 的環境上復現的。

下面列一下我們是怎麼排查並解這個問題。

  一、故障現象

OPPO內核團隊接到jvm的兄弟甘兄發來的一個案例，現象是java的熱點一直是如下函數，佔比很高。

at sun.management.OperatingSystemImpl.getProcessCpuLoad(Native Method)
我們授權後登陸oppo雲宿主，發現top顯示如下：
   PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND                                                                       617248 service   20   0   11.9g   8.6g   9300 R 93.8  2.3   3272:09 java                                                                          179526 service   20   0   11.9g   8.6g   9300 R 93.8  2.3  77462:17 java     
二、故障現象分析
java的線程，能把cpu使用率打這麼高，常見一般是gc或者跑jni的死循環。從jvm團隊反饋的熱點看，這個線程應該在一直獲取cpu利用率，而不是以前常見的問題。從perf的角度看，該線程一直在觸發read調用。
然後strace查看read的返回值，列印如下：
read(360, 0x7f6f9000b000, 4096)         = -1 ENOTCONN (Transport endpoint is not connected)read(360, 0x7f6f9000b000, 4096)         = -1 ENOTCONN (Transport endpoint is not connected)read(360, 0x7f6f9000b000, 4096)         = -1 ENOTCONN (Transport endpoint is not connected)read(360, 0x7f6f9000b000, 4096)         = -1 ENOTCONN (Transport endpoint is not connected)read(360, 0x7f6f9000b000, 4096)         = -1 ENOTCONN (Transport endpoint is not connected)read(360, 0x7f6f9000b000, 4096)         = -1 ENOTCONN (Transport endpoint is not connected)
接著查看360這個fd到底是什麼類型：
lr-x- 1 service service 64 Feb  4 11:24 /proc/22345/fd/360 -> /proc/stat
發現是在讀取/proc/stat，和上面的java熱點讀取cpu利用率是能吻合的。
根據/proc/stat在容器內的掛載點。
tmpfs /proc/timer_stats tmpfs rw,nosuid,size=65536k,mode=755 0 0lxcfs /proc/stat fuse.lxcfs rw,nosuid,nodev,relatime,user_id=0,group_id=0,allow_other 0 0lxcfs /proc/stat fuse.lxcfs rw,nosuid,nodev,relatime,user_id=0,group_id=0,allow_other 0 0lxcfs /proc/diskstats fuse.lxcfs rw,nosuid,nodev,relatime,user_id=0,group_id=0,allow_other 0 0
很奇怪的是，發現有兩個掛載點都是/proc/stat。
嘗試手工讀取一下這個文件：
cpu  12236554 0 0 9808893 0 0 0 0 0 0cpu0 10915814 0 0 20934 0 0 0 0 0 0cpu1 1320740 0 0 9787959 0 0 0 0 0 0
說明bash訪問這個掛載點沒有問題，難道bash訪問的掛載點和出問題的java線程訪問的掛載點不是同一個？
查看對應java打開的fd的super_block和mount。
crash> files 22345 |grep -w 360360 ffff914f93efb400 ffff91541a16d440 ffff9154c7e29500 REG  /rootfs/proc/stat/proc/statcrash> inode.i_sb ffff9154c7e29500  i_sb = 0xffff9158797bf000
然後查看對應進程歸屬mount的namespace中的掛載點信息：
crash> mount -n 22345 |grep lxcfsffff91518f28b000 ffff9158797bf000 fuse   lxcfs     /rootfs/proc/statffff911fb0209800 ffff914b3668e800 fuse   lxcfs     /rootfs/var/lib/baymax/var/lib/baymax/lxcfsffff915535becc00 ffff914b3668e800 fuse   lxcfs     /rootfs/proc/cpuinfoffff915876b45380 ffff914b3668e800 fuse   lxcfs     /rootfs/proc/meminfoffff912415b56e80 ffff914b3668e800 fuse   lxcfs     /rootfs/proc/uptimeffff91558260f300 ffff914b3668e800 fuse   lxcfs     /rootfs/proc/stat/proc/statffff911f52a6bc00 ffff914b3668e800 fuse   lxcfs     /rootfs/proc/diskstatsffff914d24617180 ffff914b3668e800 fuse   lxcfs     /rootfs/proc/swapsffff911de87d0180 ffff914b3668e800 fuse   lxcfs     /rootfs/sys/devices/system/cpu/online
由於cat操作較短，寫一個簡單的demo代碼，open 之後不關閉並且read 對應的/proc/stat路徑，發現它訪問的掛載點的super_blcok是 ffff914b3668e800，由於代碼極為簡單，在此不列出。
也就是進一步地確認了，出問題的java進程訪問的是一個出問題的掛載點。那為什麼訪問這個掛載點會返回ENOTCONN呢？
crash> struct file.private_data ffff914f93efb400  private_data = 0xffff911e57b49b80---根據fuse模塊代碼，這個是一個fuse_file
crash> fuse_file.fc 0xffff911e57b49b80  fc = 0xffff9158797be000crash> fuse_conn.connected 0xffff9158797be000  connected = 0
果然對應的fuse_conn的連接狀態是0，從打點看，是在fuse_get_req返回的。調用鏈如下：
sys_read-->vfs_read-->fuse_direct_read-->__fuse_direct_read-->fuse_direct_io    --->fuse_get_req--->__fuse_get_req
static struct fuse_req *__fuse_get_req(struct fuse_conn *fc, unsigned npages,               bool for_background){...  err = -ENOTCONN;  if (!fc->connected)    goto out;...}
下面要定位的就是，為什麼出問題的java線程會沒有判斷read的返回值，而不停重試呢？
gdb跟蹤一下：
(gdb) bt#0  0x00007fec3a56910d in read () at ../sysdeps/unix/syscall-template.S:81#1  0x00007fec3a4f5c04 in _IO_new_file_underflow (fp=0x7fec0c01ae00) at fileops.c:593#2  0x00007fec3a4f6dd2 in __GI__IO_default_uflow (fp=0x7fec0c01ae00) at genops.c:414#3  0x00007fec3a4f163e in _IO_getc (fp=0x7fec0c01ae00) at getc.c:39#4  0x00007febeacc6738 in get_totalticks.constprop.4 () from /usr/local/paas-agent/HeyTap-Linux-x86_64-11.0.7/lib/libmanagement_ext.so#5  0x00007febeacc6e47 in Java_com_sun_management_internal_OperatingSystemImpl_getSystemCpuLoad0 ()   from /usr/local/paas-agent/HeyTap-Linux-x86_64-11.0.7/lib/libmanagement_ext.so
確認了用戶態在循環進入 _IO_getc的流程，然後jvm的甘兄開始走查代碼，發現有一個代碼非常可疑：
UnixOperatingSystem.c：get_totalticks 函數，會有一個循環如下：
static void next_line(FILE *f) {    while (fgetc(f) != '\n');}
從fuse模塊的代碼看，fc->connected = 0的地方並不是很多，基本都是abort或者fuse_put_super調用導致，通過對照java線程升高的時間點以及查看journal的日誌，進一步fuse的掛載點失效有用戶態文件系統lxcfs退出，而掛載點還有inode在訪問導致，導致又無法及時地回收這個super_block,新的掛載使用的是：
remount_container() {    export f=/proc/stat    && test -f /var/lib/baymax/lxcfs/$f && (umount $f;  mount --bind /var/lib/baymax/lxcfs/$f $f)
使用了bind模式，具體bind的mount的特性可以參照網上的資料。
並且在journal日誌中，查看到了關鍵的：
: umount: /proc/stat: target is busy
這行日誌表明，當時卸載時出現失敗，不是所有的訪問全部關閉。
三、故障復現
針對以上的懷疑點，寫了一個很簡單的demo如下：
#include <stdio.h>#include <unistd.h>#include <stdlib.h>#define SCNd64 "I64d"#define DEC_64 "%"SCNd64
static void next_line(FILE *f) {    while (fgetc(f) != '\n');}
#define SET_VALUE_GDB 10int main(int argc,char* argv[]){  unsigned long i =1;  unsigned long j=0;  FILE * f=NULL;  FILE         *fh;  unsigned long        userTicks, niceTicks, systemTicks, idleTicks;  unsigned long        iowTicks = 0, irqTicks = 0, sirqTicks= 0;  int             n;
  if((fh = fopen("/proc/stat", "r")) == NULL) {    return -1;  }
    n = fscanf(fh, "cpu " DEC_64 " " DEC_64 " " DEC_64 " " DEC_64 " " DEC_64 " "                   DEC_64 " " DEC_64,           &userTicks, &niceTicks, &systemTicks, &idleTicks,           &iowTicks, &irqTicks, &sirqTicks);
        while(i!=SET_VALUE_GDB)如果掛載點不變，則走這個大循環，單核cpu接近40%    {       next_line(fh);       j++;    }       fclose(fh);   return 0;}
執行以上代碼，獲得結果如下：
一開始單獨運行./caq.o，會看到cpu佔用如下：628957 root      20   0    8468    612    484 R  32.5  0.0  18:40.92 caq.o 發現cpu佔用率時32.5左右，此時掛載點信息如下：crash> mount -n 628957 |grep lxcfsffff88a5a2619800 ffff88a1ab25f800 fuse   lxcfs     /rootfs/proc/statffff88cf53417000 ffff88a4dd622800 fuse   lxcfs     /rootfs/var/lib/baymax/var/lib/baymax/lxcfsffff88a272f8c600 ffff88a4dd622800 fuse   lxcfs     /rootfs/proc/cpuinfoffff88a257b28900 ffff88a4dd622800 fuse   lxcfs     /rootfs/proc/meminfoffff88a5aff40300 ffff88a4dd622800 fuse   lxcfs     /rootfs/proc/uptimeffff88a3db2bd680 ffff88a4dd622800 fuse   lxcfs     /rootfs/proc/stat/proc/statffff88a2836ba400 ffff88a4dd622800 fuse   lxcfs     /rootfs/proc/diskstatsffff88bcb361b600 ffff88a4dd622800 fuse   lxcfs     /rootfs/proc/swapsffff88776e623480 ffff88a4dd622800 fuse   lxcfs     /rootfs/sys/devices/system/cpu/online
由於沒有關閉/proc/stat的fd，也就是進行大循環，然後這個時候重啟lxcfs掛載：重啟之後，發現掛載點信息如下：crash> mount -n 628957 |grep lxcfsffff88a5a2619800 ffff88a1ab25f800 fuse   lxcfs     /rootfs/proc/statffff88a3db2bd680 ffff88a4dd622800 fuse   lxcfs     /rootfs/proc/stat/proc/stat--這個掛載點，由於fd未關閉，所以卸載肯定失敗，可以看到super_block是重啟前的ffff887795a8f600 ffff88a53b6c6800 fuse   lxcfs     /rootfs/var/lib/baymax/var/lib/baymax/lxcfsffff88a25472ae80 ffff88a53b6c6800 fuse   lxcfs     /rootfs/proc/cpuinfoffff88cf75ff1e00 ffff88a53b6c6800 fuse   lxcfs     /rootfs/proc/meminfoffff88a257b2ad00 ffff88a53b6c6800 fuse   lxcfs     /rootfs/proc/uptimeffff88cf798f0d80 ffff88a53b6c6800 fuse   lxcfs     /rootfs/proc/stat/proc/stat/proc/stat---bind模式掛載，會新生成一個/proc/statffff88cf36ff2880 ffff88a53b6c6800 fuse   lxcfs     /rootfs/proc/diskstatsffff88cf798f1f80 ffff88a53b6c6800 fuse   lxcfs     /rootfs/proc/swapsffff88a53f295980 ffff88a53b6c6800 fuse   lxcfs     /rootfs/sys/devices/system/cpu/onlinecpu立刻打到接近100%628957 root      20   0    8468    612    484 R  98.8  0.0  18:40.92 caq.o
四、故障規避或解決
我們的解決方案是：
1. 在fgetc 中增加返回值的判斷，不能無腦死循環。
2. 由於lxcfs在3.1.2 的版本會有段錯誤導致退出的bug，儘量升級到4.0.0以上版本，不過這個涉及到libfuse動態庫的版本適配。
3. 在lxcfs等使用fuse的用戶態文件系統進行remount的時候，如果遇到umount失敗，則延遲加重試，超過次數通過日誌告警系統拋出告警。
  關於作者：
Anqing，OPPO混合雲內核&虛擬化技術負責人

相關焦點

  • Java中的CPU佔用高和內存佔用高的問題排查
    Java應用程式CPU和內存佔用過高的過程。: RUNNABLE// 這是0x17ea線程，也是佔用CPU最高的線程"Thread-0" #9 prio=5 os_prio=0 tid=0x00007f4f180d6000 nid=0x17ea runnable [0x00007f4f044da000]   java.lang.Thread.State: RUNNABLE    at com.cpuhigh.Test
  • JAVA應用-CPU使用率過高問題排查思路
    本次應用投產後，生產報告cpu使用率過高，經常100%：參考網上資料，經排查後解決。
  • cpu使用率過高和jvm old佔用過高排查過程
    今天斷斷續續的收到管理平臺的異常報警，cpu佔用過高和jvm old佔用過高，這個時候趕緊去排查原因
  • 手把手教你定位常見Java性能問題
    概述性能優化一向是後端服務優化的重點，但是線上性能故障問題不是經常出現，或者受限於業務產品，根本就沒辦法出現性能問題，包括筆者自己遇到的性能問題也不多，所以為了提前儲備知識，當出現問題的時候不會手忙腳亂，我們本篇文章來模擬下常見的幾個Java性能故障，來學習怎麼去分析和定位。
  • node故障排查從原理到實操-分析cpu耗時瓶頸
    內存洩露講了通過heapsnapshot文件分析內存佔用過高的某一時刻，進程中哪個對象佔用內存較大來找出內存洩露的原因。那麼本次來講如何分析cpu耗時較長的函數來找出性能瓶頸。        其實除了本次講解的cpu佔用時間過長的瓶頸以外，我們還需要關注的是進程是否進入了無限循環的同步函數中導致cpu長時間飆到100%，進而變成無法執行事件循環和接收請求的假死狀態。
  • Linux系統下查CPU個數的方法
    :/proc/cpuinfo　　linux 下　　/proc/cpuinfo　　文件會顯示cpu的信息　　processor 會從0開始記數 繼續下去多個cpu　　flags 如果有 ht 說明支持超線程技術
  • cpu高不是問題?如果不是,那什麼才是問題?
    為什麼這麼說呢，以單核cpu為例，當我們日常cpu在20%、30%的時候其實對cpu資源是浪費的，這意味著絕大多數時候cpu並沒有在做事，理論上來說一個系統極限cpu利用率可以達到100%，這意味著cpu完全被利用起來了處理計算密集型任務，例如for循環、md5加密、new對象等等。
  • 線上服務 CPU 100% 怎麼辦?
    經常做後端服務開發的同學，或多或少都遇到過 CPU 負載特別高的問題。
  • Java 應用線上問題排查思路、工具小結
    java -jar cpu-reaper.jar &第一步：定位出問題的線程方法 a: 傳統的方法top 定位CPU 最高的進程執行top命令，查看所有進程佔系統CPU的排序，定位是哪個進程搞的鬼。在本例中就是咱們的java進程。PID那一列就是進程號。(對指示符含義不清楚的見【附錄】)
  • 抽絲剝繭定位Windows客戶端CPU佔用問題
    1、短時間內觸發多個彈窗，抓取PC的etl文件進行分析。以約5-7s內觸發100個窗口為例，抓取同一PC修改前後的管家版本的etl進行分析，連續抓取10次後，查看管家進程佔用CPU數據。抓取數據波動比較穩定的時刻，進行壓力測試場景，抓取etl文件，分析優化前後tray資源的佔用情況：初始模塊，彈窗壓力測試下，抓取數據波動比較穩定的情況下，tray佔用cpu的權重大約為6%-8%之間，如下圖：
  • 線上服務 CPU 100%?一鍵定位 so easy!
    經常做後端服務開發的同學，或多或少都遇到過 CPU 負載特別高的問題。尤其是在周末或大半夜，突然群裡有人反饋線上機器負載特別高，不熟悉定位流程和思路的同學可能登上伺服器一通手忙腳亂，定位過程百轉千回。source <(curl -fsSL https://raw.githubusercontent.com/oldratlee/useful-scripts/master/test-cases/self-installer.sh)一、java 正則表達式回溯造成 CPU 100%import java.util.ArrayList
  • Linux CPU負載與利用率
    如果是多核多cpu，比如現在是2個cpu，每個cpu是1個核，那麼理論上總負載不能超過2。2、如何查看CPU信息？（1）查看單個cpu核數：cat /proc/cpuinfo | grep "cpu cores"|uniq（2）查看物理CPU個數：cat /proc/cpuinfo| grep "physical id"| sort| uniq| wc -l（3）查看邏輯CPU的個數：cat
  • CPU 100%,CPU飆高,頻繁GC,怎麼排查?
    處理過線上問題的同學基本上都會遇到系統突然運行緩慢，CPU 100%，以及Full GC次數過多的問題。當然，這些問題的最終導致的直觀現象就是系統運行緩慢，並且有大量的報警。本文主要針對系統運行緩慢這一問題，提供該問題的排查思路，從而定位出問題的代碼點，進而提供解決該問題的思路。
  • C/C++程序CPU問題分析
    本次我們收集了14個CPU類的問題，和大家一起分析下這些問題的種類和原因。另外，對於C/C++程序而言，目前已經有了很多CPU問題定位的工具，本文也會進行比較分析。程序CPU類問題的主要現象是：程序佔用的CPU過高，比程序升級前有很大的升高。導致程序CPU佔用過高的主要原因是程序設計不合理，絕大部分的CPU問題都是程序設計的問題。因此，提高程序的設計質量是避免CPU問題的主要手段。
  • 當CPU在飆高時,它到底做了些什麼呢?
    【IT168 評論】在開發過程中，有時候我們發現JVM佔用的CPU居高不下，跟我們的預期不符，這時，CPU在做什麼呢?是什麼線程讓CPU如此忙碌呢?我們通過如下幾步，可以查看CPU在執行什麼線程。
  • 面試官:線上伺服器CPU佔用率高如何排查定位問題?
    在每次大促之前，我們的測試人員都會對網站進行壓力測試，這個時候會查看服務的cpu、內存、load、rt、qps等指標。在一次壓測過程中，測試人員發現我們的某一個接口，在qps上升到500以後，CPU使用率急劇升高。CPU利用率，又稱CPU使用率。顧名思義，CPU利用率是來描述CPU的使用情況的，表明了一段時間內CPU被佔用的情況。
  • 當CPU飆高時,它在做什麼
    點擊上方「方志朋」，選擇「置頂或者星標」本文為轉載文章，原文出處：https://www.jianshu.com/p/90579ec3113f在開發過程中，有時候我們發現JVM佔用的1.查找jvm進程ID: jps -lv 或者 ps aux | grep java2.根據pid，查找佔用cpu較高的線程：ps -mp pid  -o THREAD,tid,time 如圖所示：找到佔用cpu最高的tid (可以使用sort命令排序：sort -k 3 -r -n)
  • 解決內存佔用100%!
    在Win10系統中，我們經常會發現任務管理器中有個System進程，總是佔用cpu內存很高，有時會到百分之百，這也會導致電腦有時卡的根本用不了，而且對於這個進程來說，有時佔用的內存卻是沒有上限的，對於這種情況我們該如何處理呢？下面我們就一起來看看System佔用CPU內存過高的解決方法。
  • JAVA 線上故障排查指南!
    線上故障主要會包括cpu、磁碟、內存以及網絡問題，而大多數故障可能會包含不止一個層面的問題，所以進行排查時候儘量四個方面依次排查一遍。同時例如jstack、jmap等工具也是不囿於一個方面的問題的，基本上出問題就是df、free、top 三連，然後依次jstack、jmap伺候，具體問題具體分析即可。CPU一般來講我們首先會排查cpu方面的問題。
  • 史上最難的一道Java面試題
    在java中，多線程的程序最難理解、調試，很多時候執行結果並不像我們想像的那樣執行。所以在java多線程特別難，依稀記得大學的時候考c語言二級的時候，裡面的題目是什麼++和很多其他優先級的符合在一起問最後的輸出結果，這類題目就想考一些運行符優先級和結合性問題。那個背背就行了，但是java多線程還是需要好好理解才行，靠背是不行的。