bug现场谜之进程为什么消失了

谜之bug现场:进程好好的不见了,找不到他杀的任何证据,总不能是自杀吧。复活它之后某一个时刻消失,再复活再消失...

2023年06月02日

目录


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=xx.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 掘金专栏发表前重读、优化、勘误

相关文章推荐