一次 RocketMQ 进程自动退出排查经验分享（实战篇）

2019 年 10 月 31 日
筆記

1、背景

公司一个 RocketMQ 集群由4主4从组成，突然其中3台服务器“竟然”在同一时间下线，其监控显示如下：

依次查看三台机器的监控图形，时间戳几乎完美“吻合”，不可思议吧。

2、故障分析

出现问题，先二话不说，马上重启各服务器，尽快恢复集群，降低对业务的影响，接下来开始对日志进行分析。

Java 进程自动退出(rocketmq 本身就是一个java进程)，一种最常见的问题是由于内存溢出或由于内存泄漏导致进程发送Crash等。由于我们的启动参数中未配置

-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/opt/jvmdump

这两个参数，不能直接根据是否生成 dump 文件，那退而求其次去查看其GC日志，将GC日志下载到本地，然后可以使用一个在线gc日志分析工具：https://gceasy.io/ ，将 gc 日志上传后会给出图形化的展示，其图如下：

发现垃圾回收很正常。

既然 Java 进程不是由于内存溢出等问题导致的退出，那又会是什么原因呢？那我们来看一下那个点的broker的日志，其关键日志截图如下：

发现 broker 日志中有打印出 shutdownHook，表示在进程退出之前执行了启动时注册时的退出钩子函数，说明 broker 是正常停止的，并且也不可能是 kill -9 命令，肯定是显示的执行了 shutodown 或 kill 命令，于是立马使用 history 命令查看历史命令，都未在指定时间执行过该命令，并且切换到 root 命令后，同样使用 history 命令，并未发现端倪。

但我始终相信，肯定是执行了手动执行了 kill 命令导致进程退出的，经过网上查找查，得知可以通过查阅系统日志/var/log/messages 来查看系统命令的调用，于是乎把日志文件下载到本地，开始搜索 kill 关键字，发现如下日志：

发现最近一次 kill 命令是在25号的凌晨1点多，停止 rocketmq 集群，并使用 bin/mqbroker -c conf/broker-b.conf & 进行了重新启动。

这个命令是有问题的，没有使用 nohup ，如果会话失效，该进程就会被退出，为了验证，我们再查一下进程退出时的日志：

发现在故障发生点确实有 Removed 相关的日志。

故障原因基本分析到位了，运维在启动的时候没有使用 nohup 来启动，故马上排查刚启动的集群的方式，重新重启刚启动的 Broker。

RocketMQ优雅重启小建议：

首先将 broker 的写权限关闭，命令如下： bin/mqadmin updateBrokerConfig -b 192.168.x.x:10911 -n 192.168.x.x:9876 -k brokerPermission -v 4
通过 rocketmq-console 查看该broker的写入TPS，当写入TPS降为0后，再使用 kill pid 关闭 rocketmq 进程。温馨提示：将broker的写权限关闭后，非顺序消息不会立马拒绝，而是需要等客户端路由信息更新后，不会在往该broker上发送消息，故这个过程需要等待。
启动 rocketmq nohup bin/mqbroker -c conf/broker-a.conf /dev/null 2>&1 &
恢复该节点的写权限 bin/mqadmin updateBrokerConfig -b 192.168.x.x:10911 -n 192.168.x.x:9876 -k brokerPermission -v 6

本文的故障分析与处理就介绍到这里，本文重点讲解了故障的分析过程以及 RocketMQ Broker 优雅停机的方案。其中关于RocketMQ 优雅停机参考了“瓜农老梁” 公众号的文章：RocketMQ集群生产环境节点下线操作–【实战笔记】

作者介绍：丁威，《RocketMQ技术内幕》作者，RocketMQ 社区布道师，公众号：中间件兴趣圈维护者，目前已陆续发表源码分析Java集合、Java 并发包(JUC)、Netty、Mycat、Dubbo、RocketMQ、Mybatis等源码专栏。