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 优雅停机的方案。