如何解决生产环境宕机问题

最新推荐文章于 2023-02-07 19:03:10 发布

weixin_34111819

最新推荐文章于 2023-02-07 19:03:10 发布

阅读量631

点赞数 1

文章标签： java python 运维

原文链接：https://my.oschina.net/u/3803405/blog/1834998

版权

2019独角兽企业重金招聘Python工程师标准>>>

写在前面：该篇宕机问题的排查难度远比上一篇（记一次解决线上OOM的心路历程）大的太多，上一篇中内存泄漏的问题是有迹可循的，本次的宕机在业务日志上没有任何征兆，另外本文有许多值得深挖的点，希望读者能找到自己感兴趣的点进行深挖，并将心得体会留言在评论区，让大家共同进步。

现象：zabbix告警生产环境应用shutdown，通过堡垒机登入生产环境，查看应用容器进程，并发现没有该业务应用的相应进程，第一感觉进程在某些条件下被系统杀死了，然后查看容器日志，发现均没异常可寻。

问题：

1、为何会没有应用进程及异常的日志输出？如果真的是系统杀死了应用进程，是什么条件触发了它？

2、测试环境、UAT环境为何从未有这样的情况，差别在哪？

排查：

首先去查看生产环境系统资源情况及相应容器的配置，查得该台生产机器的总内存是8G：

接着查看该应用所在容器环境的变量设置：

此处可以看到这里为java设置的最大内存为4G，接着我们又查看了部署在本台机器上的另一个应用环境的设置，结果和该应用一样，设置的内存大小为4G。

我们继续查看了该机器上的其他java应用，发现另外还部署了一个本地queue（activitymq），且设置的最大占用内存为1G,此时似乎已经可以猜测。

由于机器的总内存不够，当应用在申请新的内存时，由于环境变量设置的缘故并没有去触发GC，而是直接申请内存，系统方发现总内存已经不够用，于是直接将该应用进程杀死。

为了验证上面的说法，我们查找系统的相关日志：

清晰地看到：Feb 23 00:01:09 us-app01 kernel: Out of memory: Kill process 14157 (java) score 619 or sacrifice child，此处说明的确是系统杀死了应用进程。

根据这里的系统日志查询资料得知，系统会为每一块新分配的内存添加跟踪记录至low memory，当low memory的内存耗尽同时有需要新分配内存时，内核便会触发Kill process，此处为什么系统选择了kill该应用进程，我的猜想是一该应用进程属于用户进程，它的结束并不会影响系统的正常运行，二是由于该应用最大可用内存设置的不合理性，需要新分配内存来存储对象就发生在其中。

由于当时的进程已经被系统杀死，我们无法得知当时具体内存的使用及分配情况，作为参考依据我们选择查看相同环境下的另一台机器的内存情况：

此处可以看出系统的总内存为7967m，low memory的总内存也为7967,（64位的系统，系统总内存与low memory相同），当前low memory已经使用7832（low memory = used + buff/cache）。

种种迹象表明：由于该应用及部署在同一台机器上的另一个应用，其环境中最大可用内存设置的不合理（系统总内存8G，这两个应用的最大可用内存设置为4G，同时机器上还有一个本地queue）性，导致其内部在申请内存时由于系统的low memory被耗尽，触使系统杀死了该应用进程。

临时解决：

减少应用环境中的设置的最大可用内存，重启应用。

继续解决：

应用重启后的一段时间（几天后），我们查看应用使用的内存情况：

我们想到该应用满足的业务量很小并没有那种数据量特别大的场景，为何系统会使用掉这么多的内存呢，于是我们决定对该应用从代码角度上进行一些可行的调优。

首先使用jmp dump出内存快照，并导入jprofiler，借助jprofiler进行分析：

从上图我们可以看到char[]占用了651m的内存，String占用的是10m左右，显然这里对char类型的使用或者处理是有问题的，我们进一步查看到底是什么地方使用了char[]，又有哪些大的char[]实例，以及其中都存了怎样的数据：

这里我们看到有将近20个char[]实例的大小都超过了10m，其中最大的已然有30m，我们再查看这里都存了哪些数据：

此处可以看到其中有一些业务数据的记录，另外其内存数据中还有部分公司内部任务中心的一些任务信息（此处就不截图出来了），于是我们隐隐感觉到是不是任务平台做了什么事情，比如收集日志什么的，我们继续查看其引用情况：

看到此处的rabbit基本可以断定了就是任务中心client的引用，项目中其他地方并没有用到rabbit，于是我们找到任务中心的维护人员进行询问，他们的答案是不会去收集应用的日志的（我们心里的答案也是这，又不是日志平台的client，任务中心团队不会做这么傻的事）。

然而我们在char[]中的确看到的都是任务平台的信息这是怎么回事？于是我们查看任务平台客户端的源码及对外的api，看看能有什么线索，最终锁定了一个问题，任务平台客户端使用了线程池，并且默认的线程池中线程最多为100（这个是有些坑，简单说明，任务中心是通过queue实现的，服务端发送任务消息，client收到后消费）。

我们再看到截图中的线程，隐隐也是任务中心client的线程池中的线程，于是我们进一步查找到底哪里才会使用char[]，并且会有业务数据，查看全局代码后我们发现对于应用中任务消息的处理器并没有直接使用char[]，组内一位同学提醒是不是使用log4j打日志处理不当的原因，想一想就目前现状而言，这种说法说的通，于是我们在每一个任务处理器中查看日志上有没有大对象的输出，果然找到了一些（订单、库存等....）。

private List<AmazonOrderInfo> getAmazonOrderNotInLocal(CustomerSalesChannelVO channel) {

List<AmazonOrderInfo> amazonOrderInfoList = new ArrayList<>();

try {

Date nowTime = new Date();

Date toTime = new Date(nowTime.getTime() - 121000);

Date fromTime = new Date(nowTime.getTime() - 720000);

amazonOrderInfoList = amazonOrderService.getAmazonOrderInfoNotInLocal(channel, fromTime, toTime);

BizLogger.info("get amazon new order when amazon inventory feedback, result ： " + amazonOrderInfoList);

} catch (Exception e) {

BizLogger.syserror("getAmazonOrderNotInLocal error,", e);

}

return amazonOrderInfoList;