性能排查｜ Java误调Shell命令引发的血案

朱雀 2022-10-06 13:57 185阅读 0赞

## 背景 ##

前几天在UAT环境出现了一个问题，任务表大量待解压的任务，部分有I/O操作的服务越来越慢甚至处于停滞状态，导致大量数据延迟发送给下游而触频繁预警。由于该平台是部门所有数据入口，因此会造成很多大量用户无法开展日常操作，需要紧急处理。经过查看监控，可以看到当天监控UAT两台机器`memory`、`thread`、`network`、`cpu`都比较正常，但是唯独`load average`从上礼拜某一天开始持续上升，并且UAT 两台机器的`load average`轨迹都是持续上升(`我们服务器CPU是6核，服务正常的时候平均负载均低于5，事故当天处于最高点位置`)

**UAT 服务器1**  
![watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0V2YW5fTGV1bmc_size_16_color_FFFFFF_t_70_pic_center][]  
**UAT 服务器2**  
![watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0V2YW5fTGV1bmc_size_16_color_FFFFFF_t_70_pic_center 1][]

## 分析 ##

从上面的监控图可以知道，上面比较异常的现象是`CPU使用率低，而高负载`，于是可以从该方向入手。

负载表示的是“等待进程的平均数”。有过排查经验的同学应该知道，一般情况下，`CPU使用率低，而负载高` 。 比较常见的是等待磁盘I/O完成的进程较多，所以导致大量进程处于`运行态或者不可中断状态`。

### 疑似凶手 ###

目前我们的服务可能出现I/O磁盘操作的场景有以下几种:

*  本地磁盘IO读写过多导致大量I/O
    
     *  分析：当时我们本地磁盘空间足够，磁盘I/O操作仅有日志操作，因此可以排除
 *  数据库有慢SQL
    
     *  分析：当时数据库操作一切正常，数据库读写操作速度无异常，数据库服务器也没有异常指标，因此可以排除
 *  外接`网络文件系统`NAS发生故障，进程没办法拿到资源
    
     *  分析：我们服务器挂在了NAS服务器，大量文件是存放在NAS服务器上，因此I/O操作极其频繁。并且从上面监控图可以看到，两台服务器同时负载从上周某一天持续上升，由于我们UAT服务器其中一台机只有少量服务在跑（基于http负载均衡），正常情况下那台服务器不应该跟另一台服务器（所有核心应用几乎都在另一台机）同时出现性能问题，看起来应该是某些共享的资源出现问题，才会导致两台机同时出现故障。基本可以往这个方向继续排查。

### 自我怀疑 ###

此时得到的线索是：**某一天才突然开始出现`load average`持续上升** 和 **疑似外接网络存储NAS故障**，看起来像是因为突然上线了`某个跟NAS I/O操作的功能`导致的，不然不应该那一天之后突然持续上升。后经过我询问得知，果然`load average`开始上升那天，我们同事上过一个`housekeeing`服务，该服务是用于每隔半小时定期遍历并且清理NAS服务器上的过期文件，如无意外，这次事故就是这个服务引起。于是我觉得让同事立马在UAT两台服务器把这个服务停了，但是再次观察监控，发现`负载并没有因此有明显下降`，**难道这个新上的服务不是我们要找的`root cause`?**

### 看到希望 ###

这时候我想到`housekeeping service`有个逻辑是调用`shell script`去查询`NAS文件系统`的过期文件，看起来跟这个问题吻合。于是我怀疑是否有僵尸进程，虽然这个服务已经停了，但是僵尸进程依然不断地执行`shell script`，占用着服务器资源。于是我分别在两台UAT服务器执行`ps -ef | grep 'javaadm'` 查看服务器上是否有大量僵尸进程。果然发现有数百条僵尸进程如下(由于服务器敏感，以下是模拟数据)：

javaadm 117582 1 Jun09 ? 00:00:00 /bin/sh -c find /APP/ \ (-path /APP/XXX/...-o -path .. ) -a -prune -o -type  f - name ... head -150
    javaadm 117585 117582 Jun09 ? 00:00:00 find /APP/ (-path /APP/XXX/...-o -path .. ) -a -prune -o -type  f - name ... head -150
    javaadm 117586 1 Jun09 ? 00:00:00 /bin/sh -c find /APP/ \ (-path /APP/XXX/...-o -path .. ) -a -prune -o -type  f - name ... head -150
    javaadm 117587 117586 Jun09 ? 00:00:00 find /APP/ (-path /APP/XXX/...-o -path .. ) -a -prune -o -type  f - name ... head -150
    ...

果然不出所料，这明显看起来是有些线程执行完没关闭资源导致的

### 找到root cause ###

查看`housekeeping service`代码，果然发现了代码里调用完`shell script`没有关闭流，伪代码（`经过脱敏处理`）如下:

BufferedReader reader = null
    try{ 
        List<String> lists = new ArrayList<>();
        f = executor.submit((Callable) ()->{ 
          BufferedReader bufferedReader ;
          Process process = null;
          try{ 
            final ProcessBuilder b = new ProcessBuilder("/bin/sh","-c",shellCommand);
            //启动进程
            process = b.start();
            final Inputstream errorStream = process.getErrorStream();
            clearErrorStream(errorStream);
            bufferedReader = new BufferedReader(new InputStreamReader(process.getInputStream()));
            return bufferedReader;
          }catch (Exception ex){ 
            LOGGER.warn("Exception :{}",ex);
            return null;
          }
          });
          //超时时间120秒
          reader = f.get(Constant.TIMEOUT,TimeUnit.MILLISESECONDS);
          
          ....省略
        }
        
        
      }

从上面的代码可以知道，它在通过线程池创建了一个`future`实例，并且在其阻塞线程里开启了一个进程调用本地`shell script`指令去遍历所有过期文件，但是线程内并没有任何关闭进程实例的操作，同时经过询问该功能的同事得知，他在做自测的时候就发现，有时候这个动态生成的 `shell script`随机遍历到比较深的大文件夹时，会遇到`shell command hung`住的情况，可以确定这就是导致大量僵尸进程的`root casue`。

## 解决方案 ##

根据上面的排查结果，把服务器上这类型的`command`对应的进程`kill`掉，监控可以看到`load average`明显下降。  
![watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0V2YW5fTGV1bmc_size_16_color_FFFFFF_t_70_pic_center 2][]

代码也加入了如下`关闭进程实例的操作`，问题就解决了

finall{ 
      if(!Object.isNull(process)){ 
      process.destroy();
      }
    }

问题解决后，`load average`从监控可以看到数值稳定在4以下  
![watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0V2YW5fTGV1bmc_size_16_color_FFFFFF_t_70_pic_center 3][]

[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0V2YW5fTGV1bmc_size_16_color_FFFFFF_t_70_pic_center]: /images/20221005/370e2cc0b1074ef39332788aa202b850.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0V2YW5fTGV1bmc_size_16_color_FFFFFF_t_70_pic_center 1]: /images/20221005/ba47e423ffce4940b7c0b7e471ed1984.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0V2YW5fTGV1bmc_size_16_color_FFFFFF_t_70_pic_center 2]: /images/20221005/e8aabb17f731441387029d33d3ebcf36.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L0V2YW5fTGV1bmc_size_16_color_FFFFFF_t_70_pic_center 3]: /images/20221005/2695be557f024dc293dd983041948c3e.png