[SERVER-31193] initial sync collection clone progress goes above 100% Created: 20/Sep/17  Updated: 27/Oct/23  Resolved: 03/Oct/17

Status: Closed
Project: Core Server
Component/s: Replication
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Minor - P4
Reporter: Zakhar Kleyman Assignee: William Schultz (Inactive)
Resolution: Works as Designed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Backwards Compatibility: Fully Compatible
Operating System: ALL
Participants:

 Description   

Initial sync collection clone progress can go above 100% sometimes

mongodb.log.2017-09-20T19-08-46:2017-09-19T19:09:09.630+0000 I -        [repl writer worker 6]   logs.task_logg collection clone progress: 120458/181002659 0% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-19T19:10:29.284+0000 I -        [repl writer worker 6]   logs.task_logg collection clone progress: 270881/181002659 0% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-19T19:11:44.902+0000 I -        [repl writer worker 6]   logs.task_logg collection clone progress: 424906/181002659 0% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-19T19:12:58.293+0000 I -        [repl writer worker 5]   logs.task_logg collection clone progress: 568699/181002659 0% (documents copied)
...
mongodb.log.2017-09-20T19-08-46:2017-09-20T10:40:26.194+0000 I -        [repl writer worker 13]   logs.task_logg collection clone progress: 174839559/181002659 96% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-20T10:41:35.607+0000 I -        [repl writer worker 7]   logs.task_logg collection clone progress: 176056703/181002659 97% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-20T10:42:47.384+0000 I -        [repl writer worker 7]   logs.task_logg collection clone progress: 177297337/181002659 97% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-20T10:44:03.085+0000 I -        [repl writer worker 7]   logs.task_logg collection clone progress: 178395481/181002659 98% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-20T10:45:30.069+0000 I -        [repl writer worker 7]   logs.task_logg collection clone progress: 179401683/181002659 99% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-20T10:46:47.082+0000 I -        [repl writer worker 8]   logs.task_logg collection clone progress: 180586508/181002659 99% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-20T10:48:28.651+0000 I -        [repl writer worker 8]   logs.task_logg collection clone progress: 181819211/181002659 100% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-20T10:49:30.019+0000 I -        [repl writer worker 8]   logs.task_logg collection clone progress: 182639239/181002659 100% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-20T10:50:52.630+0000 I -        [repl writer worker 8]   logs.task_logg collection clone progress: 183469037/181002659 101% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-20T10:51:52.210+0000 I -        [repl writer worker 8]   logs.task_logg collection clone progress: 184232500/181002659 101% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-20T10:53:02.187+0000 I -        [repl writer worker 8]   logs.task_logg collection clone progress: 185050359/181002659 102% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-20T10:54:28.684+0000 I -        [repl writer worker 5]   logs.task_logg collection clone progress: 186264701/181002659 102% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-20T10:55:35.874+0000 I -        [repl writer worker 5]   logs.task_logg collection clone progress: 187067096/181002659 103% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-20T10:57:21.672+0000 I -        [repl writer worker 4]   logs.task_logg collection clone progress: 188209948/181002659 103% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-20T10:58:46.080+0000 I -        [repl writer worker 4]   logs.task_logg collection clone progress: 189385860/181002659 104% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-20T11:00:02.865+0000 I -        [repl writer worker 4]   logs.task_logg collection clone progress: 190523332/181002659 105% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-20T11:01:20.087+0000 I -        [repl writer worker 4]   logs.task_logg collection clone progress: 191835349/181002659 105% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-20T11:02:28.444+0000 I -        [repl writer worker 4]   logs.task_logg collection clone progress: 193119747/181002659 106% (documents copied)
mongodb.log.2017-09-20T19-08-46:2017-09-20T11:03:47.338+0000 I -        [repl writer worker 4]   logs.task_logg collection clone progress: 194298584/181002659 107% (documents copied)

This collection had a lot of documents so initial sync took a few hours (~16) and it seems that it grew by 7% within that time period. The total number of documents to copy wasn't updated since the initial sync started though resulting in inaccurate progress % info.



 Comments   
Comment by William Schultz (Inactive) [ 28/Sep/17 ]

There are two relevant pieces of data that are used by the CollectionCloner when calculating its cloning progress: documentsCopied and documentsToCopy. The first value, documentsCopied, is a precise and meaningful quantity: it is the exact number of documents that have been copied from the sync source since the beginning of the collection cloning process. The quantity documentsToCopy, however, is less precise, and is more of an approximation. The documentsToCopy value is set at the beginning of collection cloning by counting the number of documents in the remote collection. During the collection cloning process, however, the number of documents in the remote collection may increase or decrease, depending on whether there are documents being inserted to or deleted from the sync source's collection. In theory, the correct value for documentsToCopy would be the final number of documents actually copied i.e. the value of documentsCopied when cloning has finished. That future value, though, is impossible to know. There is no way to compute the exact cloning progress, since there is no way to know how many future inserts or deletes will occur during the cloning process. Because of this fact (which is inherent to the cloning process itself) it should be possible to see a clone progress that exceeds 100%, or to see a clone that finishes with a progress percentage less than 100%.

You can see here where the actual progress percentage is calculated. It uses _done/_total * 100 as the progress percentage. _done is updated with the _documentsCopied value every time new documents arrive, and _total is set to _documentToCopy at the beginning of the collection clone.

In the future it may help users if we make it clearer that this progress value is to be considered an approximation, to alleviate confusion.

Generated at Thu Feb 08 04:26:16 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.