Resumable Initial Sync in MongoDB 4.4
Rate this article
Hello, everyone. My name is Nuno and I have been working with MongoDB databases for almost eight years now as a sysadmin and as a Technical Services Engineer.
One of the most common challenges in MongoDB environments is when a replica set member requires a resync and the Initial Sync process is interrupted for some reason.
Interruptions like network partitions between the sync source and the node doing the initial sync causes the process to fail forcing it to restart from scratch to ensure database consistency.
This began to be particularly problematic when faced with a large dataset sizes which can take up to several days when they are in terms of terabytes.
You may have already noticed that I am talking in the past tense as this is no longer a problem you need to face. I am very happy to share with you one of the latest enhancements introduced by MongoDB in v4.4: Resumable Initial Sync.
Resumable Initial Sync now enables nodes doing initial sync to survive events like transient network errors or a sync source restart when fetching data from the sync source node.
The time spent when recovering replica set members with Initial Sync procedures on large data environments has two common challenges:
- Falling off the oplog
- Transient network failures
MongoDB became more resilient to these types of failures with MongoDB v3.4 by adding the ability to pull newly added oplog records during the data copy phase, and more recently with MongoDB v4.4 and the ability to resume the initial sync where it left off.
The initial sync process will restart the interrupted or failed command and keep retrying until the command succeeds a non-resumable error occurs, or a period specified by the parameter initialSyncTransientErrorRetryPeriodSeconds passes (default: 24 hours). These restarts are constrained to use the same sync source, and are not tolerant to rollbacks on the sync source. That is if the sync source experiences a rollback, the entire initial sync attempt will fail.
Resumable errors include retriable errors when
ErrorCodes::isRetriableError return true which includes all network errors as well as some other transient errors.The
ErrorCodes::NamespaceNotFound, ErrorCodes::OperationFailed, ErrorCodes::CursorNotFound, or ErrorCodes::QueryPlanKilled mean the collection may have been dropped, renamed, or modified in a way which caused the cursor to be killed. These errors will cause ErrorCodes::InitialSyncFailure and will be treated the same as transient retriable errors (except for not killing the cursor), mark ErrorCodes::isRetriableError as true, and will allow the initial sync to resume where it left off.On
ErrorCodes::NamespaceNotFound, it will skip this entire collection and return success. Even if the collection has been renamed, simply resuming the query is sufficient since we are querying by UUID; the name change will be handled during oplog application.All other errors are
non-resumable.The default retry period is 24 hours (86,400 seconds). A database administrator can choose to increase this period with the following command:
1 // Default is 86400 2 db.adminCommand({ 3 setParameter: 1, 4 initialSyncTransientErrorRetryPeriodSeconds: 86400 5 })
Note: The 24-hour value is the default period estimated for a database administrator to detect any ongoing failure and be able to act on restarting the sync source node.
The full resumable behavior will always be available between 4.4 nodes regardless of FCV - Feature Compatibility Version. Between 4.2 and 4.4 nodes, the initial sync will not be resumable during the query phase of the
CollectionCloner (where we are actually reading data from collections), nor will it be resumable after collection rename, regardless of which node is 4.4. Resuming after transient failures in other commands will be possible when the syncing node is 4.4 and the sync source is 4.2.During initial sync, the sync source node can become unavailable (either due to a network failure or process restart) and still, be able to resume and complete.
Here are examples of what messages to expect in the logs.
Initial Sync attempt successfully started:
1 {"t":{"$date":"2020-11-10T19:49:21.826+00:00"},"s":"I", "c":"INITSYNC", "id":21164, "ctx":"ReplCoordExtern-0","msg":"Starting initial sync attempt","attr":{"initialSyncAttempt":1,"initialSyncMaxAttempts":10}} 2 {"t":{"$date":"2020-11-10T19:49:22.905+00:00"},"s":"I", "c":"INITSYNC", "id":21173, "ctx":"ReplCoordExtern-1","msg":"Initial syncer oplog truncation finished","attr":{"durationMillis":0}}
Messages caused by network failures (or sync source node restart):
1 {"t":{"$date":"2020-11-10T19:50:04.822+00:00"},"s":"D1", "c":"INITSYNC", "id":21078, "ctx":"ReplCoordExtern-0","msg":"Transient error occurred during cloner stage","attr":{"cloner":"CollectionCloner","stage":"query","error":{"code":6,"codeName":"HostUnreachable","errmsg":"recv failed while exhausting cursor :: caused by :: Connection closed by peer"}}} 2 {"t":{"$date":"2020-11-10T19:50:04.823+00:00"},"s":"I", "c":"INITSYNC", "id":21075, "ctx":"ReplCoordExtern-0","msg":"Initial Sync retrying cloner stage due to error","attr":{"cloner":"CollectionCloner","stage":"query","error":{"code":6,"codeName":"HostUnreachable","errmsg":"recv failed while exhausting cursor :: caused by :: Connection closed by peer"}}}
Initial Sync is resumed after being interrupted:
1 {"t":{"$date":"2020-11-10T19:51:43.996+00:00"},"s":"D1", "c":"INITSYNC", "id":21139, "ctx":"ReplCoordExtern-0","msg":"Attempting to kill old remote cursor with id: {id}","attr":{"id":118250522569195472}} 2 {"t":{"$date":"2020-11-10T19:51:43.997+00:00"},"s":"D1", "c":"INITSYNC", "id":21133, "ctx":"ReplCoordExtern-0","msg":"Collection cloner will resume the last successful query"}
Data cloners resume:
1 {"t":{"$date":"2020-11-10T19:53:27.345+00:00"},"s":"D1", "c":"INITSYNC", "id":21072, "ctx":"ReplCoordExtern-0","msg":"Cloner finished running stage","attr":{"cloner":"CollectionCloner","stage":"query"}} 2 {"t":{"$date":"2020-11-10T19:53:27.347+00:00"},"s":"D1", "c":"INITSYNC", "id":21069, "ctx":"ReplCoordExtern-0","msg":"Cloner running stage","attr":{"cloner":"CollectionCloner","stage":"setupIndexBuildersForUnfinishedIndexes"}} 3 {"t":{"$date":"2020-11-10T19:53:27.349+00:00"},"s":"D1", "c":"INITSYNC", "id":21072, "ctx":"ReplCoordExtern-0","msg":"Cloner finished running stage","attr":{"cloner":"CollectionCloner","stage":"setupIndexBuildersForUnfinishedIndexes"}} 4 {"t":{"$date":"2020-11-10T19:53:27.350+00:00"},"s":"D1", "c":"INITSYNC", "id":21148, "ctx":"ReplCoordExtern-0","msg":"Collection clone finished","attr":{"namespace":"test.data"}} 5 {"t":{"$date":"2020-11-10T19:53:27.351+00:00"},"s":"D1", "c":"INITSYNC", "id":21057, "ctx":"ReplCoordExtern-0","msg":"Database clone finished","attr":{"dbName":"test","status":{"code":0,"codeName":"OK"}}}
Data cloning phase completes successfully. Oplog cloning phase starts:
1 {"t":{"$date":"2020-11-10T19:53:27.352+00:00"},"s":"I", "c":"INITSYNC", "id":21183, "ctx":"ReplCoordExtern-0","msg":"Finished cloning data. Beginning oplog replay","attr":{"databaseClonerFinishStatus":"OK"}} 2 {"t":{"$date":"2020-11-10T19:53:27.353+00:00"},"s":"I", "c":"INITSYNC", "id":21195, "ctx":"ReplCoordExtern-3","msg":"Writing to the oplog and applying operations until stopTimestamp before initial sync can complete","attr":{"stopTimestamp":{"":{"$timestamp":{"t":1605038002,"i":1}}},"beginFetchingTimestamp":{"":{"$timestamp":{"t":1605037760,"i":1}}},"beginApplyingTimestamp":{"":{"$timestamp":{"t":1605037760,"i":1}}}}} 3 {"t":{"$date":"2020-11-10T19:53:27.359+00:00"},"s":"I", "c":"INITSYNC", "id":21181, "ctx":"ReplCoordExtern-1","msg":"Finished fetching oplog during initial sync","attr":{"oplogFetcherFinishStatus":"CallbackCanceled: oplog fetcher shutting down","lastFetched":"{ ts: Timestamp(1605038002, 1), t: 296 }"}}
Initial Sync completes successfully and statistics are provided:
1 {"t":{"$date":"2020-11-10T19:53:27.360+00:00"},"s":"I", "c":"INITSYNC", "id":21191, "ctx":"ReplCoordExtern-1","msg":"Initial sync attempt finishing up"} 2 {"t":{"$date":"2020-11-10T19:53:27.360+00:00"},"s":"I", "c":"INITSYNC", "id":21192, "ctx":"ReplCoordExtern-1","msg":"Initial Sync Attempt Statistics","attr":{"statistics":{"failedInitialSyncAttempts":0,"maxFailedInitialSyncAttempts":10,"initialSyncStart":{"$date":"2020-11-10T19:49:21.826Z"},"initialSyncAttempts":[],"appliedOps":25,"initialSyncOplogStart":{"$timestamp":{"t":1605037760,"i":1}},"initialSyncOplogEnd":{"$timestamp":{"t":1605038002,"i":1}},"totalTimeUnreachableMillis":203681,"databases":{"databasesCloned":3,"admin":{"collections":2,"clonedCollections":2,"start":{"$date":"2020-11-10T19:49:23.150Z"},"end":{"$date":"2020-11-10T19:49:23.452Z"},"elapsedMillis":302,"admin.system.keys":{"documentsToCopy":2,"documentsCopied":2,"indexes":1,"fetchedBatches":1,"start":{"$date":"2020-11-10T19:49:23.150Z"},"end":{"$date":"2020-11-10T19:49:23.291Z"},"elapsedMillis":141,"receivedBatches":1},"admin.system.version":{"documentsToCopy":1,"documentsCopied":1,"indexes":1,"fetchedBatches":1,"start":{"$date":"2020-11-10T19:49:23.291Z"},"end":{"$date":"2020-11-10T19:49:23.452Z"},"elapsedMillis":161,"receivedBatches":1}},"config":{"collections":3,"clonedCollections":3,"start":{"$date":"2020-11-10T19:49:23.452Z"},"end":{"$date":"2020-11-10T19:49:23.976Z"},"elapsedMillis":524,"config.system.indexBuilds":{"documentsToCopy":0,"documentsCopied":0,"indexes":1,"fetchedBatches":0,"start":{"$date":"2020-11-10T19:49:23.452Z"},"end":{"$date":"2020-11-10T19:49:23.591Z"},"elapsedMillis":139,"receivedBatches":0},"config.system.sessions":{"documentsToCopy":1,"documentsCopied":1,"indexes":2,"fetchedBatches":1,"start":{"$date":"2020-11-10T19:49:23.591Z"},"end":{"$date":"2020-11-10T19:49:23.801Z"},"elapsedMillis":210,"receivedBatches":1},"config.transactions":{"documentsToCopy":0,"documentsCopied":0,"indexes":1,"fetchedBatches":0,"start":{"$date":"2020-11-10T19:49:23.801Z"},"end":{"$date":"2020-11-10T19:49:23.976Z"},"elapsedMillis":175,"receivedBatches":0}},"test":{"collections":1,"clonedCollections":1,"start":{"$date":"2020-11-10T19:49:23.976Z"},"end":{"$date":"2020-11-10T19:53:27.350Z"},"elapsedMillis":243374,"test.data":{"documentsToCopy":29000000,"documentsCopied":29000000,"indexes":1,"fetchedBatches":246,"start":{"$date":"2020-11-10T19:49:23.976Z"},"end":{"$date":"2020-11-10T19:53:27.349Z"},"elapsedMillis":243373,"receivedBatches":246}}}}}} 3 {"t":{"$date":"2020-11-10T19:53:27.451+00:00"},"s":"I", "c":"INITSYNC", "id":21163, "ctx":"ReplCoordExtern-3","msg":"Initial sync done","attr":{"durationSeconds":245}}
The new InitialSync statistics from replSetGetStatus.initialSyncStatus can be useful to review the initial sync progress status.
Starting in MongoDB 4.2.1, replSetGetStatus.initialSyncStatus metrics are only available when run on a member during its initial sync (i.e., STARTUP2 state).
The metrics are:
- syncSourceUnreachableSince - The date and time at which the sync source became unreachable.
- currentOutageDurationMillis - The time in milliseconds that the sync source has been unavailable.
- totalTimeUnreachableMillis - The total time in milliseconds that the member has been unavailable during the current initial sync.
- totalTimeUnreachableMillis - The total time in milliseconds that the member has been unavailable during the current initial sync.
- operationsRetried - Total number of all operation retry attempts.
- rollBackId - The sync source's rollback identifier at the start of the initial sync attempt.
An example of this output is:
1 replset:STARTUP2> db.adminCommand( { replSetGetStatus: 1 } ).initialSyncStatus 2 { 3 "failedInitialSyncAttempts" : 0, 4 "maxFailedInitialSyncAttempts" : 10, 5 "initialSyncStart" : ISODate("2020-11-06T20:16:21.649Z"), 6 "initialSyncAttempts" : [ ], 7 "appliedOps" : 0, 8 "initialSyncOplogStart" : Timestamp(1604693779, 1), 9 "syncSourceUnreachableSince" : ISODate("2020-11-06T20:16:32.950Z"), 10 "currentOutageDurationMillis" : NumberLong(56514), 11 "totalTimeUnreachableMillis" : NumberLong(56514), 12 "databases" : { 13 "databasesCloned" : 2, 14 "admin" : { 15 "collections" : 2, 16 "clonedCollections" : 2, 17 "start" : ISODate("2020-11-06T20:16:22.948Z"), 18 "end" : ISODate("2020-11-06T20:16:23.219Z"), 19 "elapsedMillis" : 271, 20 "admin.system.keys" : { 21 "documentsToCopy" : 2, 22 "documentsCopied" : 2, 23 "indexes" : 1, 24 "fetchedBatches" : 1, 25 "start" : ISODate("2020-11-06T20:16:22.948Z"), 26 "end" : ISODate("2020-11-06T20:16:23.085Z"), 27 "elapsedMillis" : 137, 28 "receivedBatches" : 1 29 }, 30 "admin.system.version" : { 31 "documentsToCopy" : 1, 32 "documentsCopied" : 1, 33 "indexes" : 1, 34 "fetchedBatches" : 1, 35 "start" : ISODate("2020-11-06T20:16:23.085Z"), 36 "end" : ISODate("2020-11-06T20:16:23.219Z"), 37 "elapsedMillis" : 134, 38 "receivedBatches" : 1 39 } 40 }, 41 "config" : { 42 "collections" : 3, 43 "clonedCollections" : 3, 44 "start" : ISODate("2020-11-06T20:16:23.219Z"), 45 "end" : ISODate("2020-11-06T20:16:23.666Z"), 46 "elapsedMillis" : 447, 47 "config.system.indexBuilds" : { 48 "documentsToCopy" : 0, 49 "documentsCopied" : 0, 50 "indexes" : 1, 51 "fetchedBatches" : 0, 52 "start" : ISODate("2020-11-06T20:16:23.219Z"), 53 "end" : ISODate("2020-11-06T20:16:23.348Z"), 54 "elapsedMillis" : 129, 55 "receivedBatches" : 0 56 }, 57 "config.system.sessions" : { 58 "documentsToCopy" : 1, 59 "documentsCopied" : 1, 60 "indexes" : 2, 61 "fetchedBatches" : 1, 62 "start" : ISODate("2020-11-06T20:16:23.348Z"), 63 "end" : ISODate("2020-11-06T20:16:23.538Z"), 64 "elapsedMillis" : 190, 65 "receivedBatches" : 1 66 }, 67 "config.transactions" : { 68 "documentsToCopy" : 0, 69 "documentsCopied" : 0, 70 "indexes" : 1, 71 "fetchedBatches" : 0, 72 "start" : ISODate("2020-11-06T20:16:23.538Z"), 73 "end" : ISODate("2020-11-06T20:16:23.666Z"), 74 "elapsedMillis" : 128, 75 "receivedBatches" : 0 76 } 77 }, 78 "test" : { 79 "collections" : 1, 80 "clonedCollections" : 0, 81 "start" : ISODate("2020-11-06T20:16:23.666Z"), 82 "test.data" : { 83 "documentsToCopy" : 29000000, 84 "documentsCopied" : 714706, 85 "indexes" : 1, 86 "fetchedBatches" : 7, 87 "start" : ISODate("2020-11-06T20:16:23.666Z"), 88 "receivedBatches" : 7 89 } 90 } 91 } 92 } 93 replset:STARTUP2>
Upgrade your MongoDB database to the new v4.4 and take advantage of the new Resumable Initial Sync feature. Your deployment will now survive transient network errors or a sync source restarts.
If you have questions, please head to our developer community website where the MongoDB engineers and the MongoDB community will help you build your next big idea with MongoDB.
Rate this article