回复
技术干货 | MongoDB 新特性 Mirrors Reads Bug 发现及分析
laomugua
发布于 2023-2-2 14:55
浏览
0收藏
背景
Mongo 组件持续运营过程中，发现“断言”异常，在排除人为操作和客户端异常等噪音后，仍然广泛分布在4系版本中。疑似有大鱼，于是集中力量专项治理。经分析，发现 Mongo Core Bug 一项，Mongo Shell Bug 一项，已提交 issue，并得到官网确认。其中 SERVER-72532 影响了4.4.11+,5.0.4+, 6.0.0+, 6.2.0-rc4+版本，属于影响范围较大的重要发现，官方暂未发布修复版本。其中 MONGOSH-1357 官方已确认，在版本1.6.2进行修复。下面具体描述问题的分析过程。
定位问题
通过对线上 MongoDB 集群构建告警监控体系，其中一套线上集群持续发生“客户端断言数量”告警，告警信息如下：
内容：监控点名称：MongoDB-断言数量；总告警条数:45。详细：
[实例：shard1_38_27001，主机：XXX，期望值：0，当前值：8];
[实例：shard1_39_27001，主机：XXX，期望值：0，当前值：8];
[实例：shard2_40_27002，主机：XXX，期望值：0，当前值：4];
[实例：shard2_41_27002，主机：XXX，期望值：0，当前值：8];
[实例：shard2_42_27002，主机：XXX，期望值：0，当前值：9];
[实例：shard3_44_27003，主机：XXX，期望值：0，当前值：10];
[实例：shard3_45_27003，主机：XXX，期望值：0，当前值：10];
……
问题分析
问题分析主要从 MongoDB 的指标、日志、源码三个方面进行分析。其中指标方面主要从访问量、主机、集群各项指标对比分析，尝试找到告警指标与其它监控指标的关联关系。日志方面主要找到导致发生异常的日志详细信息。源码方面主要基于指标、日志分析源码中的问题。
3.1 指标分析
通过对告警信息、监控指标的分析得出以下结论：
- 通过告警信息可以发现，每个分片每秒都有10个左右的断言，10分钟就是6000个断言，这项指标明显偏高，而且判断不会是由于人为操作错误导致的异常，大概率是应用程序或其它 MongoDB 进程导致。
- 通过告警信息可以发现，发生断言数告警的节点均为各分片的从节点，主节点未发生告警，而应用程序不连从节点，在排除了 Exporter 嫌疑后，基本确定是 MongoDB 内部组件引起的告警。
- 通过分析监控指标发现，集群的断言数与应用的操作数趋势一致。由此可以初步判断由于应用的 CRUD 操作触发了集群内部的异常。
3.2 日志分析
默认的日志级别未打印出有效的异常信息，因此在某个分片的主、从节点分别执行db.setLogLevel(1)命令，将日志级别调高后，抓取更详细的信息如下：
{\”t\”:{\”$date\”:\”2023-01-04T16:02:45.079+08:00\”},\”s\”:\”I\”, \”c\”:\”NETWORK\”, \”id\”:51800, \”ctx\”:\”conn141332\”,\”msg\”:\”client metadata\”,\”attr\”:{\”remote\”:\”主节点IP:51588\”,\”client\”:\”conn141332\”,\”doc\”:{\”driver\”:{\”name\”:\”NetworkInterfaceTL\”,\”version\”:\”4.4.14\”},\”os\”:{\”type\”:\”Linux\”,\”name\”:\”CentOS Linux release 7.6.1810 (Core) \”,\”architecture\”:\”x86_64\”,\”version\”:\”Kernel 3.10.0-957.el7.x86_64\”}}}}
{\”t\”:{\”$date\”:\”2023-01-04T16:02:45.080+08:00\”},\”s\”:\”I\”, \”c\”:\”ACCESS\”, \”id\”:20250, \”ctx\”:\”conn141332\”,\”msg\”:\”Authentication succeeded\”,\”attr\”:{\”mechanism\”:\”SCRAM-SHA-256\”,\”speculative\”:true,\”principalName\”:\”__system\”,\”authenticationDatabase\”:\”local\”,\”remote\”:\”主节点IP:51588\”,\”extraInfo\”:{}}}
{\”t\”:{\”$date\”:\”2023-01-04T17:08:21.381+08:00\”},\”s\”:\”D1\”, \”c\”:\”-\”, \”id\”:23074, \”ctx\”:\”conn141332\”,\”msg\”:\”User assertion\”,\”attr\”:{\”error\”:\”CommandNotFound: no such command: \’shardVersion\’\”,\”file\”:\”src/mongo/db/service_entry_point_common.cpp\”,\”line\”:1361}}
{\”t\”:{\”$date\”:\”2023-01-04T17:08:21.381+08:00\”},\”s\”:\”D1\”, \”c\”:\”COMMAND\”, \”id\”:21966, \”ctx\”:\”conn141332\”,\”msg\”:\”Assertion while executing command\”,\”attr\”:{\”command\”:\”shardVersion\”,\”db\”:\”orderdb\”,\”error\”:\”CommandNotFound: no such command: \’shardVersion\’\”}}
{\”t\”:{\”$date\”:\”2023-01-04T17:08:21.381+08:00\”},\”s\”:\”I\”, \”c\”:\”COMMAND\”, \”id\”:51803, \”ctx\”:\”conn141332\”,\”msg\”:\”Slow query\”,\”attr\”:{\”type\”:\”command\”,\”ns\”:\”orderdb.$cmd\”,\”command\”:\”unrecognized\”,\”numYields\”:0,\”ok\”:0,\”errMsg\”:\”no such command: \’shardVersion\’\”,\”errName\”:\”CommandNotFound\”,\”errCode\”:59,\”locks\”:{},\”protocol\”:\”op_msg\”,\”durationMillis\”:0}}
{\”t\”:{\”$date\”:\”2023-01-04T17:08:21.381+08:00\”},\”s\”:\”D1\”, \”c\”:\”QUERY\”, \”id\”:22790, \”ctx\”:\”conn141332\”,\”msg\”:\”Received interrupt request for unknown op\”,\”attr\”:{\”opId\”:3652609564}}*注意：日志抓取后，记得执行db.setLogLevel(0)恢复日志级别。
相似的日志只在分片的从节点发生，主节点并没有类似的日志，通过分析日志初步得出以下结论：
- 导致 User asserts 指标告警的原因是 MongoDB 接收到了不支持的命令：shardVersion。
- 发出 shardVersion 命令的是主节点 IP:51588，根据部署架构，该节点是 shard13 分片的主节点一个随机端口，因此该主节点是作为客户端主动向从节点发出了一个 MongoDB 不支持的操作命令 shardVersion。
- 代码 src/mongo/db/service_entry_point_common.cpp 1361 行，命令解析失败确实会触发 user asserts 指标一直上涨。
- 基于对 MongoDB 特性的掌握，主从节点之间主要有以下几种情况会发生交互，一是互发心跳，二是数据同步，三是数据预热，得出以下结论：
- 互发心跳方面，从日志中未显示任何心跳信息，且如果心跳包解析异常会触发主从节点切换，而实际情况集群整体运行稳定，因此排除心跳包解析异常的可能性，排除。
- 主从数据同步方面，4.4版本对主从数据同步的方式确实有优化，在4.4以上版本，从节点会以订阅的方式感知主节点的 oplog 变化，当主节点发生写操作时，会将 oplog 源源不断的推送到从节点，而4.4以下版本是从节点通过长轮询的方式主动拉取主节点的 oplog。因此，数据同步均是从节点作为客户端主动连接主节点，与日志信息不符，排除。
- 数据预热方面，4.4版本新增了主、从节点预热特性，通过查阅官方文档，主节点在发生 count、distinct、find、findAndModify、update 操作时，会向从节点主动发起数据预热，即主节点会主动连接从节点按一定的比例进行指令推送，符合现象，因此将排查方向锁定在数据预热部分。
3.3 源码分析
通过以上指标、日志的分析初步锁定在主节点发生 count、distinct、find、findAndModify、update 操作时，主节点会主动将数据推送给从节点进行预热。对比分析4.4版本与4.2版本代码发现 count、distinct、find、findAndModify、update 命令在4.4.11版本发生了变更。在4.4.11版本组装请求时，添加了 shardVersion 命令。在 write_commands.cpp 拼接请求时 shardVersion 被错误地写在请求的第一个字段，导致 shardVersion 被 MongoDB 解析成一条命令而导致解析失败。
if (const auto& shardVersion = _commandObj.getField(\”shardVersion\”);
!shardVersion.eoo()) {
bob->append(shardVersion);
}
bob->append(\”find\”, _commandObj[\”update\”].String());
extractQueryDetails(_updateOpObj, bob);
bob->append(\”batchSize\”, 1);
bob->append(\”singleBatch\”, true);3.4 实操验证
通过以上分析，初步确认是由于4.4版本引入的主从节点数据预热新特性导致的命令解析失败。为了验证这个结论，尝试通过禁用数据预热来观察 user asserts 是否持续上涨。执行命令：
db.adminCommand( {
setParameter: 1,
mirrorReads: { samplingRate: 0.0 }
} )持续观察 user asserts 情况可以看出 user asserts 不再上涨。
shard13 [direct: secondary] admin> db.serverStatus().asserts
{ regular: 0, warning: 0, msg: 0, user: 10007218, rollovers: 0 }
shard13 [direct: secondary] admin> db.serverStatus().asserts
{ regular: 0, warning: 0, msg: 0, user: 10007218, rollovers: 0 }
shard13 [direct: secondary] admin> db.serverStatus().asserts
{ regular: 0, warning: 0, msg: 0, user: 10007218, rollovers: 0 }
shard13 [direct: secondary] admin> db.serverStatus().asserts
{ regular: 0, warning: 0, msg: 0, user: 10007218, rollovers: 0 }启用数据预热并恢复预热比例为默认值 0.01，持续观察 user asserts 情况可以看出 user asserts 持续上涨。
shard13 [direct: secondary] admin> db.serverStatus().asserts
{ regular: 0, warning: 0, msg: 0, user: 10007219, rollovers: 0 }
shard13 [direct: secondary] admin> db.serverStatus().asserts
{ regular: 0, warning: 0, msg: 0, user: 10007241, rollovers: 0 }
shard13 [direct: secondary] admin> db.serverStatus().asserts
{ regular: 0, warning: 0, msg: 0, user: 10007257, rollovers: 0 }到目前为止，通过分析我们已经可以确定是4.4版本 MongoDB 数据预热特性引发的内核的 Bug 导致命令解析失败，进而导致 user asserts 指标持续告警。接下来需要在官方社区上报 issue。
3.5 开源社区
MongoDB 有单独的 JIRA 系统来管理社区报告的缺陷，地址：https://jira.mongodb.org。本次发现的 issue 属于 MongoDB Core 级别的 Bug，另外，在禁用数据预热特性时，发现所使用的客户端工具 mongosh 1.6.0 版本禁用失败，报错信息如下：
db.adminCommand( {
… setParameter: 1,
… mirrorReads: { samplingRate: 0.0 }
… } )
MongoServerError: BSON field \’mirrorReads.samplingRate\’ is the wrong type \’int\’, expected type \’double\’通过客户端工具 mongo 执行成功，因此判断出客户端工具 mongosh 1.6.0 在进行小数处理时也存在缺陷，因此一共创建了两个 issue，分别是：
并且均得到了官方的有效确认。其中 SERVER-72532 影响了4.4.11以上, 5.0.4以上, 6.0.0以上, 6.2.0-rc4以上版本，属于影响范围较大的重要发现，并且修复版本官方暂未确定。MONGOSH-1357 官方已确认在版本 1.6.2 进行修复。
3.6 影响范围
数据预热属于一个从节点在备生主时性能优化的特性，对集群整体运行及应用使用不构成影响。主要影响数据预热特性及运维监控：
- 影响目前生产环境4.4.14版本分片集群 update 操作的数据预热，即主节点执行 update 操作，从节点无法对该操作的数据进行预热。
- 影响 user asserts 指标的监控，可能导致例如认证失败、连接失败等应用使用方式的问题淹没在大量的 user asserts 告警中。
解决方法
- 方法一：待官方发布修复版本后，进行版本升级，替换程序，滚动重启即可。
- 方法二：官方建议可以在每个节点禁用数据预热特性，在每个节点执行命令：
db.adminCommand( {
setParameter: 1,
mirrorReads: { samplingRate: 0.0 }
} )
方法三：官方建议可以在每个节点禁用数据预热特性，滚动重启每个 MongoDB 进程，加入–setParameter mirrorReads=\'{samplingRate: 0}’启动参数。
文章转载自公众号：Mongoing中文社区
分类
标签
已于2023-2-2 14:55:35修改
赞
收藏
回复
相关推荐
