MongoDB爱好者
垂直技术交流平台

MongoDB 新特性 Mirrors Reads Bug 发现及分析

1 背景

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 进行修复。下面具体描述问题的分析过程。

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];

……

3 问题分析

问题分析主要从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特性的掌握,主从节点之间主要有以下几种情况会发生交互,一是互发心跳,二是数据同步,三是数据预热,得出以下结论:

  – (1)互发心跳方面,从日志中未显示任何心跳信息,且如果心跳包解析异常会触发主从节点切换,而实际情况集群整体运行稳定,因此排除心跳包解析异常的可能性,排除。

  – (2)主从数据同步方面,4.4版本对主从数据同步的方式确实有优化,在4.4以上版本,从节点会以订阅的方式感知主节点的oplog变化,当主节点发生写操作时,会将oplog源源不断的推送到从节点,而4.4以下版本是从节点通过长轮询的方式主动拉取主节点的oplog。因此,数据同步均是从节点作为客户端主动连接主节点,与日志信息不符,排除。

  – (3)数据预热方面,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,分别是:

https://jira.mongodb.org/browse/SERVER-72532

https://jira.mongodb.org/browse/MONGOSH-1357

并且均得到了官方的有效确认。其中 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 告警中。

4 解决方法

– 方法一:待官方发布修复版本后,进行版本升级,替换程序,滚动重启即可。

– 方法二:官方建议可以在每个节点禁用数据预热特性,在每个节点执行命令:

db.adminCommand( {

  setParameter: 1,

  mirrorReads: { samplingRate: 0.0 }

} )

– 方法三:官方建议可以在每个节点禁用数据预热特性,滚动重启每个MongoDB进程,加入–setParameter mirrorReads=\'{samplingRate: 0}’ 启动参数。

作者:司冬雨

MongoDB 中文社区成员,现就职于中国联通软件研究院,目前专注于 MongoDB 数据库运维与技术支持,希望能够为社区贡献一份力量。

赞(19)
未经允许不得转载:MongoDB中文社区 » MongoDB 新特性 Mirrors Reads Bug 发现及分析

评论 抢沙发

评论前必须登录!