孤儿文档是怎样产生的(MongoDB orphaned document)

时间 2019-11-11

标签孤儿文档怎样产生 mongodb orphaned document 栏目 MongoDB 繁體版

原文原文链接

　　使用MongoDB的开发人员应该都据说过孤儿文档（orphaned document）这回事儿，可谓闻着沉默，遇者流泪。本文基于MongoDB3.0来看看怎么产生一个orphaned document，要求MongoDB的运行方式须要是sharded cluster，若是对这一部分还不是很了解，能够参考一下这篇文章。html

　　在MongoDB的官方文档中，对orphaned document的描述很是简单：python

　　In a sharded cluster, orphaned documents are those documents on a shard that also exist in chunks on other shards as a result of failed migrations or incomplete migration cleanup due to abnormal shutdown. Delete orphaned documents using cleanupOrphaned to reclaim disk space and reduce confusionmongodb

　　能够看到，orphaned document是指在sharded cluster环境下，一些同时存在于不一样shard上的document。咱们知道，在mongodb sharded cluster中，分布在不一样shard的数据子集是正交的，即理论上一个document只能出如今一个shard上，document与shard的映射关系维护在config server中。官方文档指出了可能产生orphaned document的状况：在chunk迁移的过程当中，mongod实例异常宕机，致使迁移过程失败或者部分完成。文档中还指出，可使用 cleanupOrphaned 来删除orphaned document。shell

　　新闻报道灾难、事故的时候，通常都有这么一个潜规则：内容越短，事情也严重。不知道MongoDB对于orphaned document是否是也采用了这个套路，一来对orphaned document发生的可能缘由描述不够详尽，二来也没有提供检测是否存在orphaned document的方法。对于cleanupOrphaned，要在生产环境使用也须要必定的勇气。dom

orphaned document产生缘由

　　做为一个没有看过MongoDB源码的普通应用开发人员，拍脑壳想一想，chuck的迁移应该有如下三个步骤：将数据从源shard拷贝到目标shard，更新config server中的metadata，从源shard删除数据。固然，这三个步骤的顺序不必定是上面的顺序。这三个步骤，若是能保证原子性，那么理论上是不会出问题的。可是，orphaned document具体怎么出现的一直不是很清楚。异步

　　前些天在浏览官方文档的时候，发现有对迁移过程描述（chunk-migration-procedure），大体过程翻译以下：ide

　　balancer向源shard发送moveChunk命令
　　源shard内部执行moveChunk命令，并保证在迁移的过程当中，新插入的document仍是写入源shard
　　若是须要的话，目标shard建立须要的索引
　　目标shard从源shard请求数据；注意，这里是一个copy操做，而不是move操做
　　在接收完chunk的最后一个文档后，目标shard启动一个同步拷贝进程，保证拷贝到在迁移过程当中又写入源shard上的相关文档
　　彻底同步以后，目标shard向config server报告新的metadata（chunk的新位置信息）
　　在上一步完成以后，源shard开始删除旧的document

　　若是能保证以上操做的原子性，在任何步骤出问题应该都没问题；若是不能保证，那么在第4，5，6，7步出现机器宕机，都有可能出问题。对于出问题的缘由，官网（chunk-migration-queuing ）是这么解释的：oop

　　the balancer does not wait for the current migration’s delete phase to complete before starting the next chunk migrationui

　　This queuing behavior allows shards to unload chunks more quickly in cases of heavily imbalanced cluster, such as when performing initial data loads without pre-splitting and when adding new shards.

　　If multiple delete phases are queued but not yet complete, a crash of the replica set’s primary can orphan data from multiple migrations.

　　简而言之，为了加速chunk 迁移的速度（好比在新的shard加入的时候，有大量的chunk迁移），所以delete phase（第7步）不会马上执行，而是放入一个队列，异步执行，此时若是crash，就可能产生孤儿文档google

产生一个orphaned document

　　基于官方文档，如何产生一个orphaned document呢？个人想法很简单：监控MongoDB日志，在出现标志迁移过程的日志出现的时候，kill掉shard中的primary！

预备知识

　　在《经过一步步建立sharded cluster来认识mongodb》一文中，我详细介绍了如何搭建一个sharded cluster，在个人实例中，使用了两个shard，其中每一个shard包括一个primary、一个secondary，一个arbiter。另外，建立了一个容许sharding的db -- test_db, 而后sharded_col这个集合使用_id分片，本文基于这个sharded cluster进行实验。但须要注意的是：在前文中，为了节省磁盘空间，我禁用了mongod实例的journal机制(启动选项中的 --nojourbal)，但在本文中，为了尽可能符合真实状况，在启动mongod的时候使用了--journal来启用journal机制。

　　另外，再补充两点，第一个是chunk迁移的条件，只有当shards之间chunk的数目差别达到必定程度才会发生迁移：

Number of Chunks	Migration Threshold
Fewer than 20	2
20-79	4
80 and greater	8

　　第二个是，若是没有在document中包含_id，那么mongodb会自动添加这个字段，其value是一个ObjectId，ObjectId由一下部分组成：

a 4-byte value representing the seconds since the Unix epoch,
a 3-byte machine identifier,
a 2-byte process id, and
a 3-byte counter, starting with a random value.

　　所以，在没有使用hash sharding key（默认是ranged sharding key）的状况下，在短期内插入大量没有携带_id字段的ducoment，会插入到同一个shard，这也有利于出现chunk分裂和迁移的状况。

准备

　　首先，得知道chunk迁移的时候日志是什么样子的，所以我用python脚本插入了一些记录，经过sh.status()发现有chunk分裂、迁移的时候去查看mongodb日志，在rs1（sharded_col这个集合的primary shard）的primary(rs1_1.log）里面发现了以下的输出：

 34 2017-07-06T21:43:21.629+0800 I NETWORK  [conn6] starting new replica set monitor for replica set rs2 with seeds 127.0.0.1:27021,127.0.0.1:27022
 48 2017-07-06T21:43:23.685+0800 I SHARDING [conn6] moveChunk data transfer progress: { active: true, ns: "test_db.sharded_col", from: "rs1/127.0.0.1:27018,127.0.0.1:27019"    , min: { _id: ObjectId('595e3e74d71ffd5c7be8c8b7') }, max: { _id: MaxKey }, shardKeyPattern: { _id: 1.0 }, state: "steady", counts: { cloned: 1, clonedBytes: 83944, cat    chup: 0, steady: 0 }, ok: 1.0, $gleStats: { lastOpTime: Timestamp 0|0, electionId: ObjectId('595e3b0ff70a0e5c3d75d684') } } my mem used: 0
 52 -017-07-06T21:43:23.977+0800 I SHARDING [conn6] moveChunk migrate commit accepted by TO-shard: { active: false, ns: "test_db.sharded_col", from: "rs1/127.0.0.1:27018,12    7.0.0.1:27019", min: { _id: ObjectId('595e3e74d71ffd5c7be8c8b7') }, max: { _id: MaxKey }, shardKeyPattern: { _id: 1.0 }, state: "done", counts: { cloned: 1, clonedBytes    : 83944, catchup: 0, steady: 0 }, ok: 1.0, $gleStats: { lastOpTime: Timestamp 0|0, electionId: ObjectId('595e3b0ff70a0e5c3d75d684') } }
 53 w017-07-06T21:43:23.977+0800 I SHARDING [conn6] moveChunk updating self version to: 3|1||590a8d4cd2575f23f5d0c9f3 through { _id: ObjectId('5937e11f48e2c04f793b1242') }     -> { _id: ObjectId('595b829fd71ffd546f9e5b05') } for collection 'test_db.sharded_col'
 54 2017-07-06T21:43:23.977+0800 I NETWORK  [conn6] SyncClusterConnection connecting to [127.0.0.1:40000]
 55 2017-07-06T21:43:23.978+0800 I NETWORK  [conn6] SyncClusterConnection connecting to [127.0.0.1:40001]
 56 2017-07-06T21:43:23.978+0800 I NETWORK  [conn6] SyncClusterConnection connecting to [127.0.0.1:40002]
 57 2017-07-06T21:43:24.413+0800 I SHARDING [conn6] about to log metadata event: { _id: "xxx-2017-07-06T13:43:24-595e3e7c0db0d72b7244e620", server: "xxx", clientAddr: "127.0.0.1:52312", time: new Date(1499348604413), what: "moveChunk.commit", ns: "test_db.sharded_col", details: { min: { _id: ObjectId(    '595e3e74d71ffd5c7be8c8b7') }, max: { _id: MaxKey }, from: "rs1", to: "rs2", cloned: 1, clonedBytes: 83944, catchup: 0, steady: 0 } }
 58 2017-07-06T21:43:24.417+0800 I SHARDING [conn6] MigrateFromStatus::done About to acquire global lock to exit critical section
 59 2017-07-06T21:43:24.417+0800 I SHARDING [conn6] forking for cleanup of chunk data
 60 2017-07-06T21:43:24.417+0800 I SHARDING [conn6] MigrateFromStatus::done About to acquire global lock to exit critical section
 61 2017-07-06T21:43:24.417+0800 I SHARDING [RangeDeleter] Deleter starting delete for: test_db.sharded_col from { _id: ObjectId('595e3e74d71ffd5c7be8c8b7') } -> { _id: MaxKey }, with opId: 6
 62 2017-07-06T21:43:24.417+0800 I SHARDING [RangeDeleter] rangeDeleter deleted 1 documents for test_db.sharded_col from { _id: ObjectId('595e3e74d71ffd5c7be8c8b7') } -> { _id: MaxKey }

　　上面第59行，“forking for cleanup of chunk data”，看起来是准备删除旧的数据了

　　因而我写了一个shell脚本: 在rs1_1.log日志中出现“forking for cleanup of chunk data”时kill掉rs1_1这个进程，脚本以下：

check_loop()
{
    echo 'checking'
    ret=`grep -c 'forking for cleanup of chunk data' /home/mongo_db/log/rs1_1.log`
    if [ $ret -gt 0 ]; then
         echo "will kill rs1 primary"
         kill -s 9 `ps aux | grep rs1_1 | awk '{print $2}'`
         exit 0
    fi

    ret=`grep -c 'forking for cleanup of chunk data' /home/mongo_db/log/rs2_1.log`
    if [ $ret -gt 0 ]; then
         echo "will kill rs2 primary"
         kill -s 9 `ps aux | grep rs2_1 | awk '{print $2}'`
         exit 0
    fi

    sleep 0.1
    check_loop
}
check_loop

第一次尝试

　第一次尝试就是使用的上面的脚本。

　　首先运行上面的shell脚本，而后另起一个终端开始插入数据，在shell脚本kill掉进程以后，当即登上rs1和rs2查看统计数据，发现并无产生orphaned document（怎么检测看第二次尝试）

　　再回看前面的日志，几乎是出现“forking for cleanup of chunk data”的同一时刻就出现了“rangeDeleter deleted 1 documents for test_db.sharded_col from”，后者代表数据已经被删除。而shell脚本0.1s才检查一次，极可能在迁移过程已经完成以后才发出kill信号。因而将kill的时机提早，在shell脚本中检查“moveChunk migrate commit accepted”（上述文档中的第52行）

　　对shell脚本的修改也很简单，替换一下grep的内容：

check_loop()
{
    echo 'checking'
    ret=`grep -c 'moveChunk migrate commit accepted' /home/mongo_db/log/rs1_1.log`
    if [ $ret -gt 0 ]; then
         echo "will kill rs1 primary"
         kill -s 9 `ps aux | grep rs1_1 | awk '{print $2}'`
         exit 0
    fi

    ret=`grep -c 'moveChunk migrate commit accepted' /home/mongo_db/log/rs2_1.log`
    if [ $ret -gt 0 ]; then
         echo "will kill rs2 primary"
         kill -s 9 `ps aux | grep rs2_1 | awk '{print $2}'`
         exit 0
    fi

    sleep 0.1
    check_loop
}
check_loop

View Code

第二次尝试

　在进行第二次尝试以前，清空了sharded_col中的记录，一遍更快产生chunk迁移。

　重复之间的步骤：启动shell脚本，而后插入数据，等待shell脚本kill掉进程后终止

　很快，shell脚本就终止了，经过ps aux | grep mongo 也证明了rs1_1被kill掉了，登陆到mongos（mongo --port 27017）

　　mongos> db.sharded_col.find().count()

　　再登陆到rs1 primary（此时因为rs1原来的primary被kill掉，新的primary是rs1-2，端口号27019）

　　rs1:PRIMARY> db.sharded_col.find({}, {'_id': 1})

　　{ "_id" : ObjectId("595ef413d71ffd4a82dea30d") }

　　{ "_id" : ObjectId("595ef413d71ffd4a82dea30e") }

　　{ "_id" : ObjectId("595ef413d71ffd4a82dea30f") }

　　再登陆到rs2 primary

　　rs2:PRIMARY> db.sharded_col.find({}, {'_id': 1})

　　{ "_id" : ObjectId("595ef413d71ffd4a82dea30f") }

　　很明显，产生了orphaned docuemnt，ObjectId("595ef413d71ffd4a82dea30f") 这条记录存在于两个shard上，那么mongodb sharded cluter认为这条记录应该存在于哪一个shard上呢，简单的办法直接用 sh.status()查看，不过这里忘了截图。另一种方式,给这条记录新加一个字段，而后分别在两个shard上查询

　　mongos> db.sharded_col.update({'_id': ObjectId("595ef413d71ffd4a82dea30f") }, {$set:{'newattr': 10}})

　　WriteResult({ "nMatched" : 1, "nUpserted" : 0, "nModified" : 1 })

　　rs1:PRIMARY> db.sharded_col.find({'_id': ObjectId("595ef413d71ffd4a82dea30f")}, {'newattr': 1})

　　{ "_id" : ObjectId("595ef413d71ffd4a82dea30f"), "newattr" : 10 }

　　rs2:PRIMARY> db.sharded_col.find({'_id': ObjectId("595ef413d71ffd4a82dea30f")}, {'newattr': 1})

　　{ "_id" : ObjectId("595ef413d71ffd4a82dea30f") }

　　这证明了这条记录在rs1这个shard上

　　此时，从新启动rs1_1, 经过在rs.status()查看rs1这个shard正常以后，从新查看sh.status()，发现结果仍是同样的。据此推断，并无journal信息恢复被终止的迁移过程。

　所以在本次实验中，ObjectId("595ef413d71ffd4a82dea30f")这条记录原本是要从rs迁移到rs2，因为人为kill掉了rs1的primary，致使迁移只进行了一部分，产生了orphaned document。回顾前面提到的迁移过程，本次实验中对rs1 primary的kill发生在第6步以前（目标shard在config server上更新metadata以前）

使用cleanupOrphaned

　　orphaned document的影响在于某些查询会多出一些记录：多出这些孤儿文档，好比前面的count操做，事实上只有3条记录，但返回的是4条记录。若是查询的时候没用使用sharding key(这里的_id）精确匹配，也会返回多余的记录，另外，即便使用了sharding key，可是若是使用了$in，或者范围查询，均可能出错。好比：　

　　mongos> db.sharded_col.find({'_id': {$in:[ ObjectId("595ef413d71ffd4a82dea30f")]}}).count()

　　mongos> db.sharded_col.find({'_id': {$in:[ ObjectId("595ef413d71ffd4a82dea30f"), ObjectId("595ef413d71ffd4a82dea30d")]}}).count()

　　上面第二条查询语句，使用了$in，理论上应该返回两条记录，单由于孤儿文档，返回了三条。

　　本质上，若是一个操做要路由到多个shard，存在orphaned document的状况下均可能出错。这让应用开发人员防不胜防，也不可能在逻辑里面兼容孤儿文档这种异常状况。

　　MongoDB提供了解决这个问题的终极武器， cleanupOrphaned，那咱们来试试看，按照官方的文档（ remove-all-orphaned-documents-from-a-shard），删除全部的orphaned document。注意，cleanupOrphaned要在shard的primary上执行;

　　Run cleanupOrphaned in the admin database directly on the mongod instance that is the primary replica set member of the shard. Do not run cleanupOrphaned on a mongos instance.

　　可是在哪个shard上执行呢，是“正确的shard“，仍是“错误的shard”呢，文档里面并无写清楚，我想在两个shard上都执行一下应该没问题吧。

　　无论在rs1，仍是rs2上执行，结果都是同样的：　

　　{

　　 "ok" : 0,

　　"errmsg" : "server is not part of a sharded cluster or the sharding metadata is not yet initialized."

　　}

　　errmsg：server is not part of a sharded cluster or the sharding metadata is not yet initialized.

　　经过sh.status()查看：

　　shards:

　　 { "_id" : "rs1", "host" : "rs1/127.0.0.1:27018,127.0.0.1:27019" }

　　{ "_id" : "rs2", "host" : "rs2/127.0.0.1:27021,127.0.0.1:27022" }

　　显然，rs一、rs2都是sharded cluster的一部分，那么可能的状况就是“sharding metadata is not yet initialized”

　　关于这个错误，在https://groups.google.com/forum/#!msg/mongodb-user/cRr7SbE1xlU/VytVnX-ffp8J 这个讨论中指出了一样的问题，但彷佛没有完美的解决办法。至少，对于讨论中提到的方法，我都尝试过，但都没做用。

总结

　　本文只是尝试复现孤儿文档，固然我相信也更多的方式能够发现孤儿文档。另外，按照上面的日志，选择在不一样的时机kill掉shard（replica set）的primary应该有不一样的效果，也就是在迁移过程当中的不一样阶段终止迁移过程。另外，经过实验，发现cleanupOrphaned指令并无想象中好使，对于某些状况下产生的孤儿文档，并不必定能清理掉。固然，也有多是个人姿式不对，欢迎读者亲自实验。

references

orphaned document

cleanupOrphaned

经过一步步建立sharded cluster来认识mongodb

chunk-migration-procedure

chunk-migration-queuing

remove-all-orphaned-documents-from-a-shard