您的位置:首页 > 运维架构 > Apache

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

2019-11-11 07:05 2576 查看

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等源码专栏。

内容来自用户分享和网络整理,不保证内容的准确性,如有侵权内容,可联系管理员处理 点击这里给我发消息
标签:  Apache RocketMQ