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

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优雅重启小建议:

  1. 首先将 broker 的写权限关闭,命令如下:

    bin/mqadmin updateBrokerConfig -b 192.168.x.x:10911 -n 192.168.x.x:9876 -k brokerPermission -v 4
    
  2. 通过 rocketmq-console 查看该broker的写入TPS,当写入TPS降为0后,再使用 kill pid 关闭 rocketmq 进程。温馨提示:将broker的写权限关闭后,非顺序消息不会立马拒绝,而是需要等客户端路由信息更新后,不会在往该broker上发送消息,故这个过程需要等待。

  3. 启动 rocketmq

    nohup bin/mqbroker -c conf/broker-a.conf  /dev/null  2>&1 &
    

    注意:nohup。

  4. 恢复该节点的写权限

    bin/mqadmin updateBrokerConfig -b 192.168.x.x:10911 -n 192.168.x.x:9876 -k brokerPermission -v 6
    

本文的故障分析与处理就介绍到这里,本文重点讲解了故障的分析过程以及 RocketMQ Broker 优雅停机的方案。

如果本文对您有所帮助的话,麻烦帮忙点个赞,谢谢。


作者介绍:
丁威,《RocketMQ技术内幕》作者,RocketMQ 社区布道师,公众号:中间件兴趣圈 维护者,目前已陆续发表源码分析Java集合、Java 并发包(JUC)、Netty、Mycat、Dubbo、RocketMQ、Mybatis等源码专栏。欢迎加入我的知识星球,构建一个高质量的技术交流社群。
在这里插入图片描述

posted @ 2019-12-29 15:51  中间件兴趣圈  阅读(1364)  评论(1编辑  收藏  举报