replica set sync process is taking long time while upgrading it to 3.2

[Arun Ramaswamy]

Hi ,

we have replica set (1 Primary, 2 Secondaries) running on 3.0 version with mmap storage engine. We have successfully upgraded one of the secondary with 3.2 wired tiger version. Whereas when trying to upgrade second secondary it is taking longer time and we are getting more often "Index Build: 2016800/16173214 12%"  in the logs and this log did not get created while upgrading first secondary replica set. Please advice what could be the reason for the delay only in replica set.

Thanks,

Arun.R

[Pooja Gupta]

Hi Arun,

If you are upgrading by adding a new replica set member and let MongoDB perform an initial sync process, Index build will be performed as part of a normal initial sync process. If your data size is large, it could be expected to take some time to finish.

However, if you are performing an in-place binary upgrade, the index should already be in place and should not need to be rebuilt. This may be the reason that your earlier upgrade does not involve index building.

For upgrading your replica set to 3.2 with minimum disruption to your operations, please follow the recommended upgrade method outlined in Upgrade a Replica Set to 3.2.

Regards,
Pooja

​

[Arun Ramaswamy]

Thanks for the response Pooja. Can you send me the link again? I am not able to open the link. Thanks again!

[Pooja Gupta]

Hi Arun,

Please find the links below:

• For initial sync: https://docs.mongodb.com/manual/core/replica-set-sync/
• For Upgrading a Replica Set to 3.2 : https://docs.mongodb.com/manual/release-notes/3.2-upgrade/#upgrade-a-replica-set-to-3-2

Regards,
Pooja

​

[arunvinupradeep]

Thanks Pooja, now I successfully upgraded it to 3.2 version. But the log file is getting increased with below command and it is consistently coming as a long running query. Can you please help?

2016-08-11T15:54:44.149+0100 I COMMAND [conn807] command local.oplog.rs command: getMore { getMore: 25051335242, collection: "oplog.rs", maxTimeMS: 2000 } cursorid:25051335242 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:86 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, oplog: { acquireCount: { r: 2 } } } protocol:op_command 59958ms

2016-08-11T15:54:44.149+0100 I COMMAND [conn809] command local.oplog.rs command: getMore { getMore: 24308032355, collection: "oplog.rs", maxTimeMS: 2000 } cursorid:24308032355 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:86 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, oplog: { acquireCount: { r: 2 } } } protocol:op_command 59958ms

2016-08-11T15:55:45.316+0100 I COMMAND [conn814] command local.oplog.rs command: getMore { getMore: 24463360438, collection: "oplog.rs", maxTimeMS: 2000 } cursorid:24463360438 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:86 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, oplog: { acquireCount: { r: 2 } } } protocol:op_command 59973ms

2016-08-11T15:55:45.316+0100 I COMMAND [conn812] command local.oplog.rs command: getMore { getMore: 21777142242, collection: "oplog.rs", maxTimeMS: 2000 } cursorid:21777142242 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:86 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, oplog: { acquireCount: { r: 2 } } } protocol:op_command 59973ms

2016-08-11T15:56:46.685+0100 I COMMAND [conn817] command local.oplog.rs command: getMore { getMore: 21741400802, collection: "oplog.rs", maxTimeMS: 2000 } cursorid:21741400802 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:86 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, oplog: { acquireCount: { r: 2 } } } protocol:op_command 59966ms

2016-08-11T15:56:46.687+0100 I COMMAND [conn819] command local.oplog.rs command: getMore { getMore: 23059663942, collection: "oplog.rs", maxTimeMS: 2000 } cursorid:23059663942 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:86 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, oplog: { acquireCount: { r: 2 } } } protocol:op_command 59968ms

2016-08-11T15:57:47.434+0100 I COMMAND [conn825] command local.oplog.rs command: getMore { getMore: 25004154293, collection: "oplog.rs", maxTimeMS: 2000 } cursorid:25004154293 keyUpdates:0 writeConflicts:0 numYields:0 nreturned:0 reslen:86 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, oplog: { acquireCount: { r: 2 } } } protocol:op_command 59993ms

[arunvinupradeep]

Hi Pooja,

We are planning to have Go/No Go decision this week and this issue is blocking our live date. can you please help me with this issue?

Thanks,

Arun.R

On Thursday, August 11, 2016 at 6:04:07 AM UTC+1, Pooja Gupta wrote:

[Pooja Gupta]

Hi Arun,

The messages you are getting in the logs are the queries by the secondary node, onto the oplog of Primary. You can refer to the Replication mechanics in secondaries for more information.
These are the normal messages that will get logged when secondaries tries to pull the oplog from the Primary by using getMore command. However, in default profiling setting, those getMore commands should not be visible.

• Have you changed db.setProfilingLevel()?
• Are there any other slow operations observed other than getMore ?

You can also capture the replica set’s performance by using db.printReplicationInfo(), db.printSlaveReplicationInfo() functions.

Regards,
Pooja

​