共计 4111 个字符，预计需要花费 11 分钟才能阅读完成。
作者：任坤
现居珠海，先后负责专职 Oracle 和 MySQL DBA，当初次要负责 MySQL、mongoDB 和 Redis 保护工作。
本文起源：原创投稿
* 爱可生开源社区出品，原创内容未经受权不得随便应用，转载请分割小编并注明起源。
1 背景
6 月 5 号 22:30 左右收到几条报警短信，线上某 mongo 集群的 shard2 呈现了主从提早，过了几分钟主动复原。原本想伪装没看见，可是过了一会又报警主从提早，尽管这次也是主动复原，然而不下来看一下心里有点不虚浮。这套环境为 3.4 集群，3 mongos + 4 shard(1 主 2 从)，主节点 priority=2，其余节点 priority=1，当网络畅通时确保主库永远在 1 节点。
2 排查
登录 grafana 查看主库的监控信息，这一时间段 cpu 和内存使用率显著回升
qps 在 22:30 左近线性降落为 0
连接数却继续暴涨
由此能够大抵推断是连贯风暴导致主库压力过大进而引发主从复制提早，具体信息须要查看 mongod.log。mongo 日志文件的益处是记录信息十分具体，害处是记录信息太多导致文件占用空间很大。为此 mongo 提供了专门的切换日志指令，但该指令只负责切换不负责清理历史日志文件，并且 mongo 本身不能设置 job 以实现定期主动切换，为此须要独自编写脚本。
创立 1 个具备 hostManager 角色的 mongo 账号 backup，编写如下一个 shell 脚本，每小时执行 1 次。
[root@ mongod]# more logrotate_mongo.sh
#!/bin/sh
MONGO_CMD=/usr/local/mongodb/bin/mongo
KEEP_DAY=7
#flush mongod log
datadir=/data/mongodb
port=27017
role=mongod
destdir=/data/backup/mongolog/${role}
if [! ‐d "${destdir}" ]; then
mkdir ‐p ${destdir}
fi
$MONGO_CMD ‐‐authenticationDatabase admin admin ‐ubackup ‐p"*****" ‐‐eval
"db.runCommand({logRotate:1})" ‐‐port $port
mv ${datadir}/mongod.log.????‐??‐??T??‐??‐?? ${destdir}/
find $destdir ‐name "mongod.log.*" ‐mtime +${KEEP_DAY} ‐exec rm ‐rf {} \;归档的日志文件如下，22:00-23:00 时间段生成的日志量比平时多出 1 个量级，由此也能够反向推断出 mongo 在这段时间压力有异样。
‐rw‐r‐‐r‐‐ 1 root root 11647760 Jun 5 18:00 mongod.log.2021‐06‐05T10‐00‐02
‐rw‐r‐‐r‐‐ 1 root root 12869316 Jun 5 19:00 mongod.log.2021‐06‐05T11‐00‐01
‐rw‐r‐‐r‐‐ 1 root root 15625361 Jun 5 20:00 mongod.log.2021‐06‐05T12‐00‐03
‐rw‐r‐‐r‐‐ 1 root root 10993819 Jun 5 21:00 mongod.log.2021‐06‐05T13‐00‐02
‐rw‐r‐‐r‐‐ 1 root root 71500070 Jun 5 22:00 mongod.log.2021‐06‐05T14‐00‐40
‐rw‐r‐‐r‐‐ 1 root root 215216326 Jun 5 23:00 mongod.log.2021‐06‐05T15‐00‐02查问对应工夫点的日志，呈现大量创立工作线程失败的信息
2021‐06‐05T22:28:00.821+0800 I ‐ [thread2] failed to create service entry worker
thread for 172.31.0.65:39890
2021‐06‐05T22:28:00.821+0800 I NETWORK [thread2] connection accepted from
172.31.0.66:45090 #4051839 (32622 connections now open)
2021‐06‐05T22:28:00.821+0800 I ‐ [thread2] pthread_create failed: Resource
temporarily unavailable
2021‐06‐05T22:28:00.821+0800 I ‐ [thread2] failed to create service entry worker
thread for 172.31.0.66:45090
2021‐06‐05T22:28:00.821+0800 I NETWORK [thread2] connection accepted from
172.31.0.65:39892 #4051840 (32622 connections now open)
2021‐06‐05T22:28:00.821+0800 I ‐ [thread2] pthread_create failed: Resource
temporarily unavailable同一时间段从库的日志：
2021‐06‐05T22:30:07.325+0800 I REPL [ReplicationExecutor] Error in heartbeat request
to 172.31.0.183:27017; ExceededTimeLimit: Couldn't get a connection within the time limit
2021‐06‐05T22:30:07.425+0800 I SHARDING [migrateThread] Waiting for replication to catch
up before entering critical section主库简直失去了响应能力，从库定时心跳发动的连贯都无奈创立，进而触发主从选举，以后从库长期被选为主库。等老主库复原响应并重新加入集群后，又从新夺回控制权。
采纳 mtools 解析日志，输入后果也验证了这一点，失常情景下 183 为主库 114 为从库，
[root@vm172‐31‐0‐183 mongod]# mloginfo mongod.log.2021‐06‐05T15‐00‐02 ‐‐rsstate
.....
RSSTATE
date host state/message
Jun 05 22:28:05 172.31.0.114:27017 PRIMARY #114 被选举为主库
Jun 05 22:36:41 172.31.0.114:27017 SECONDARY #114 被降级为从库
[root@vm172‐31‐0‐114 mongod]# mloginfo mongod.log.2021‐06‐05T14‐48‐24 ‐‐rsstate......
RSSTATE
date host state/message
Jun 05 22:31:50 172.31.0.183:27017 ROLLBACK #183 以从库身份退出集群，执行 rollback 和 recover 流程，Jun 05 22:34:48 172.31.0.183:27017 RECOVERING
Jun 05 22:35:52 172.31.0.183:27017 SECONDARY #183 的状态变为 secondary 后，因为 priority 更高因而触发了新一轮选举
Jun 05 22:36:43 172.31.0.183:27017 PRIMARY #183 从新变成了主库 接下来的问题是确认是哪些应用服务器发动的连贯风暴，shard 节点的连贯都是由 mongos 发动的，只能去查看 mongos 实例的日志。还是采纳 mtools 工具，输入如下：这个是 21:00-22:00 时间段的连贯创立信息
[root@ mongos]# mloginfo mongod.log.2021‐06‐05T14‐00‐01 ‐‐connections
......
CONNECTIONS
total opened: 8904
total closed: 5645
no unique IPs: 6
socket exceptions: 649
127.0.0.1 opened: 2683 closed: 2683
172.31.0.21 opened: 1531 closed: 733
172.31.0.28 opened: 1525 closed: 676
172.31.0.81 opened: 1520 closed: 704
172.31.0.78 opened: 1495 closed: 699
172.31.0.134 opened: 150 closed: 150这个是 22:00-23:00 时间段的连贯创立信息，很显著这个时间段有问题
[root@ mongos]# mloginfo mongod.log.2021‐06‐05T15‐00‐01 ‐‐connections
......
CONNECTIONS
total opened: 58261
total closed: 58868
no unique IPs: 7
socket exceptions: 3708
172.31.0.78 opened: 14041 closed: 14576
172.31.0.21 opened: 13898 closed: 14284
172.31.0.28 opened: 13835 closed: 13617
172.31.0.81 opened: 13633 closed: 13535
127.0.0.1 opened: 2681 closed: 2680
172.31.0.134 opened: 170 closed: 176
172.31.0.4 opened: 3 closed: 0
由此确认这次事件是由应用服务器连贯异动造成，剩下的就是将这些信息交给开发人员进一步审核。
3 总结
这个案例总体比拟好诊断，只是须要用到 2 个工具，1 个是定期切换日志的 shell 脚本，1 个是由 mongo 官网工程师编写的 mtools。它们能够帮忙咱们疾速查看日志并从中提取出诊断所需的要害信息，极大的晋升了工作效率。