bug現場謎之進程為什麼消失了?

馮兄畫戟 2022-01-07 16:44:03 阅读数:434

bug 消失

目錄


1. bug現場情况

2021年11月,客戶現場某業務系統掛掉,運維發現系統的進程沒了,看日志也沒有任何報錯信息。

運維重啟服務,系統運行正常,第二天或者隔幾天又掛掉...

值得注意的現象:周五重啟的服務,周末基本沒人用服務,系統周末正常運行,周一上班,大家一用系統就又掛了。

2. 嘗試破案

因為沒有任何錯誤日志輸出,首先想到的是由於操作系統資源限制導致的,比如內存、CPU、socket連接數、打開文件數等。如果是這樣,操作系統級別會殺死進程並記錄相關日志。

1. 查看系統級別的日志

查看系統日志:cat /var/log/messages |grep -i 'kill'

查看內核級別的日志:dmesg |grep -i 'kill'

沒有查到任何java、OOM、或者kill相關的系統級記錄。

2. 查看JVM crash日志

系統級別的日志沒有,可能是JVM本身bug造成的crash,這樣JVM在crash的時候會生成hs_err_pid_%p.log,該文件默認生成在JVM運行的工作目錄中,也可以在JVM啟動的時候指定路徑:-XX:ErrorFile=/var/log/hs_err_pid_%p.log

工作目錄中沒有找到JVM crash日志。

3. 查看OOM Heap Dump日志

系統啟動的時候如果設定了JVM參數-XX:+HeapDumpOnOutOfMemoryError-XX:HeapDumpPath=*/java.hprof並且是由OOM導致的crash,可以在對應的路徑上找到heap dump文件,使用jvisualvm這種工具分析dump文件也可以定比特問題。

該系統有設定對應的JVM參數,對應路徑上沒有dump日志輸出。

什麼日志都沒有,會不會是什麼問題導致日志沒有生成呢?因為周一客戶一旦使用就發生宕機,就懷疑是內存問題,監控一下內存吧:

4. 監控OS進程內存、JVM堆內存

使用top命令監控OS進程內存脚本:

#!/bin/bash
while true
do
datetime=$(date '+%Y-%m-%d %H:%M:%s')
echo "$datetime" >> record_new3.txt 2>&1
top -d 1 -b -n1 |grep $PID >> record_new3.txt 2>&1
sleep 60
done
複制代碼

使用jmap命令監控JVM堆內存:

#!/bin/bash
while true
do
datetime=$(date '+%Y-%m-%d %H:%M:%s')
echo "$datetime" >> record_jmap_new3.txt 2>&1
/home/jdk8u282-b08/bin/jmap -heap $PID >> record_jmap_new3.txt 2>&1
sleep 120
done
複制代碼

分析日志發現:

JVM堆內存(通過jmap命令脚本監控得出)從3G到接近14G(JVM設置的是最大堆內存16G),然後JVM會進行GC,內存就會降下來,如此往複。沒有出現堆內存溢出情况。

JAVA進程的內存(通過top命令脚本監控得出)不斷增大,最後維持在16G左右(系統內存是256G,還非常充裕)。

當JVM進行GC的時候JVM堆內存是回收了一部分,但是對於分配給操作系統JAVA進程的內存不會回收。在JVM堆中GC時,釋放的內存只是標記內存空間可用,所以這也是為什麼系統級別JAVA進程內存一直增大,最後維持一個較大的值不變(這種是堆外內存正常的情况,有另外一種情况堆外內存持續增加最終導致內存過大,進程被OS殺死,這樣的情况應該會有一些其他原因造成堆外內存异常增長,就要想辦法找出導致堆外內存异常增長的原因)。

本宕機系統的監控顯示:內存確實沒有問題:堆內存增加到一定程度後JVM進行GC,堆內存會降下來,系統進程內存最後處在一個穩定的值。

至此,筆者已經盡了最大的努力,沒有找到實際的問題,只能寫一個重啟脚本,讓宕機的系統在5分鐘內重啟:

宕機後,5分鐘重啟服務

#!/bin/bash
while true
do
log_date=$(date '+%Y-%m-%d')
sync_date=$(date '+%Y-%m-%d %H:%M:%s')
pid=`/usr/sbin/lsof -t -i tcp:7001`
logfile="/home/TAS/TAS2810/logs/restart-$log_date.log"
if [ ! -z "$pid" ];then
echo "${sync_date}::PID為:$pid,XX系統服務啟動中..." >> "$logfile"
else
echo "${sync_date}::XX系統服務不存在,重新啟動..." >> "$logfile"
cd /home/TAS/TAS2810/bin
nohup bash /home/TAS/TAS2810/bin/StartTAS.sh &
echo "${sync_date}::重新啟動完成!" >> "$logfile"
fi
sleep 300
done
複制代碼

3. 真相浮出水面

再總結下上面的情况:服務隔一段時間就掛一次,而且沒有任何錯誤的業務日志和操作系統級別的crash日志,監控內存也很正常。

那到底是什麼問題呢?進程肯定是死了,被誰殺了?他殺嗎?操作系統日志顯示沒有殺死它,內存或者JVM層次crash自殺嗎?也沒有找到任何日志。

還能怎麼排查呢?項目派來了一個該系統的架構師,穩了!

Linux有一個strack工具可以跟踪進程的信號,也就是說用這個工具,進程是怎麼退出的能够監控出來:

#!/bin/sh
nohup strace -T -tt -e trace=all -p $(netstat -tnalp | grep 7001 | grep LISTEN | awk '{print $7}' | tr -d '/java') > trace.log &
複制代碼

第二天系統宕機,通過strack輸出日志發現是系統自己退出的,確實沒有任何他殺和自殺。

另外架構師說很可能是Linux X Server調用的問題,本地環境複現一下,果然是這個問題。

具體是:在系統中有流程相關的功能,該功能會使用java的awt庫調出來gui圖形化界面,而gui的繪制是調用服務端啟動環境的X DISPLAY Server,當服務端啟動shell窗口關閉後,客戶再點擊流程功能,服務端不能找到X DISPLAY Server環境,系統就自己退出了。

這裏應該是程序日志處理上有一些問題,awt庫找不到X DISPLAY Server環境應該會報錯的,而日志上沒有任何體現,這也是問題難以找到的原因。

需要了解X DISPLAY Server更多內容,可以參考文章:SSH終端怎們正確打開Linux gui程序-Window System

怎樣修改呢?需要添加JVM參數:-Djava.awt.headless=true,該參數的含義是告訴JVM,該運行環境沒有相關顯示屏、鼠標、鍵盤等硬件,可以利用計算機後臺的資源滿足awt相關的調用(不是所有圖形化的內容都需要顯示服務的,比如在後臺產生一些圖片就不需要顯示屏)。來看一下demo理解一下這個參數:

import javax.swing.*;
import java.awt.*;
import java.awt.event.*;
public class Calculator {
static double num;
public static void main(String[] args) {
//System.setProperty("java.awt.headless", "true");
System.setProperty("java.awt.headless", "false");
System.out.println("是否是headless環境:" + java.awt.GraphicsEnvironment.isHeadless());
System.out.println("java.awt.headless 默認值:" + System.getProperty("java.awt.headless"));
// set up frame
JFrame frame = new JFrame();
frame.setSize(500, 500);
frame.setTitle("Simple Calculator");
frame.setLocationByPlatform(true);
frame.setDefaultCloseOperation(JFrame.EXIT_ON_CLOSE);
// set up panel
JPanel panel = new JPanel();
// set layout to 5x2 grid layout
panel.setLayout(new GridLayout(5, 2));
// set up answer label
JLabel answer = new JLabel();
// set up number text fields
JTextField num1 = new JTextField();
JTextField num2 = new JTextField();
// set up buttons
JButton add = new JButton();
add.setText("+");
add.addActionListener(new ActionListener() {
@Override
public void actionPerformed(ActionEvent event) {
try {
num = Double.parseDouble(num1.getText())
+ Double.parseDouble(num2.getText());
answer.setText(Double.toString(num));
} catch (Exception e) {
answer.setText("Error!");
}
}
});
JButton sub = new JButton();
sub.setText("-");
sub.addActionListener(new ActionListener() {
@Override
public void actionPerformed(ActionEvent event) {
try {
num = Double.parseDouble(num1.getText())
- Double.parseDouble(num2.getText());
answer.setText(Double.toString(num));
} catch (Exception e) {
answer.setText("Error!");
}
}
});
JButton mul = new JButton();
mul.setText("*");
mul.addActionListener(new ActionListener() {
@Override
public void actionPerformed(ActionEvent event) {
try {
num = Double.parseDouble(num1.getText())
* Double.parseDouble(num2.getText());
answer.setText(Double.toString(num));
} catch (Exception e) {
answer.setText("Error!");
}
}
});
JButton div = new JButton();
div.setText("/");
div.addActionListener(new ActionListener() {
@Override
public void actionPerformed(ActionEvent event) {
try {
num = Double.parseDouble(num1.getText())
/ Double.parseDouble(num2.getText());
answer.setText(Double.toString(num));
} catch (Exception e) {
answer.setText("Error!");
}
}
});
// add components to panel
panel.add(new JLabel("Number 1"));
panel.add(new JLabel("Number 2"));
panel.add(num1);
panel.add(num2);
panel.add(add);
panel.add(sub);
panel.add(mul);
panel.add(div);
panel.add(new JLabel("Answer"));
panel.add(answer);
// add panel to frame and make it visible
frame.add(panel);
frame.setVisible(true);
}
}
複制代碼

執行代碼,如果是Oracle JDK1.8,默認是java.awt.headlessfalse,而openjdk默認值是true。上面的代碼打開一個簡單的gui的計算器,如果設置java.awt.headless=true,就是告訴JVM沒有相關的顯示服務,就會報錯:

為什麼報錯呢?awt要調出來gui程序,JVM參數headless的true設置告訴JVM運行環境沒有顯示服務,不支持gui程序。

上面代碼設置java.awt.headless=false,執行輸出:

這裏報錯信息是不能連接到啟動環境中的X DISPLAY Server,本地環境中有安裝Microsoft VcXsrv X Server,設置的display port為3600,因此在JVM啟動的shell環境中設置export DISPLAY=172.26.18.37:3600,重新執行:

java.awt.headless=true什麼場景時候用呢?比如,要生成圖片,沒有用到顯示服務,但是用awt庫,下面demo所示:

import java.awt.Graphics;
import java.awt.image.BufferedImage;
import java.io.File;
import javax.imageio.ImageIO;
public class TestCHSGraphic {
public static void main (String[] args) throws Exception {
// 設置Headless模式
//System.setProperty("java.awt.headless", "true");
//System.setProperty("java.awt.headless", "false");
System.out.println("是否是headless環境:" + java.awt.GraphicsEnvironment.isHeadless());
System.out.println("java.awt.headless 默認值:" + System.getProperty("java.awt.headless"));
BufferedImage bi = new BufferedImage(200, 100, BufferedImage.TYPE_INT_RGB);
Graphics g = bi.getGraphics();
g.drawString(new String("Headless Test".getBytes(), "utf-8"), 50, 50);
ImageIO.write(bi, "jpeg", new File("test.jpg"));
}
}
複制代碼

這裏如果java.awt.headless設置為false,並且在JVM的運行環境中沒有X DISPLAY Server,就會出現和上面一樣找不到X DISPLAY Server的報錯。

4. 總結

  1. 不要先入為主,認為程序一定是被自殺或者他殺的。事實錶明程序是自己退出的。
  2. 日志是解决問題的最佳突破口,如果有日志就從日志出發。沒有日志也能說明一些問題,比如本例中要盡早排除掉內存或者JVM crash導致問題的排查方向。
  3. 不能完全依賴日志,代碼有時候處理不當會把日志吃掉。嘗試複現問題能够找出突破口。
  4. 有些問題找不出原因可能是知識的盲區,多了解相關支持能幫助排查問題。
  5. 問題排查要一點點縮小排查範圍,一定不能想當然,要像教孩子一樣親身實踐,一點點排除。很多情况由於自己想當然,很小的點疏忽了,會浪費大量時間。

更新記錄

  • 2022-01-07 12:15 掘金專欄發錶前重讀、優化、勘誤

相關文章推薦


微信公眾號搜索“馮兄畫戟”關注馮兄,第一時間圍觀更多精彩內容。
原文鏈接:bug現場謎之進程為什麼消失了?

版权声明:本文为[馮兄畫戟]所创,转载请带上原文链接,感谢。 https://gsmany.com/2022/01/202201071644025361.html