Oplog.rs getMore taking more time on secondary PlanSummary:COLSCAN

Ops and Admin Replication
1

Hi Team,

We see the the following query taking more time in secondary. There is no change in the indexing for the collection from the previous releases. With 4.0 we are not seeing much time. but we are currently using 4.2 and seeing this more frequently. We are not sure if this causing any impact with respect to the performance issues we are seeing in 4.2. Can you please tell us why this flooding frequently and how to avoid this?

2022-11-09T19:46:05.056+0000 I COMMAND [conn5243758] command local.oplog.rs command: getMore { getMore: 3744042275538770656, collection: “oplog.rs”, batchSize: 13981010, maxTimeMS: 5000, term: 2, lastKnownCommittedOpTime: { ts: Timestamp(1668023164, 1355), t: 2 }, $replData: 1, $oplogQueryData: 1, $readPreference: { mode: “secondaryPreferred” }, $clusterTime: { clusterTime: Timestamp(1668023164, 1369), signature: { hash: BinData(0, B5927874271B36B9316E6F71FCB7AEC44C84E677), keyId: 7150119648661340164 } }, $db: “local” } originatingCommand: { find: “oplog.rs”, filter: { ts: { $gte: Timestamp(1667995887, 563) } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 60000, batchSize: 13981010, term: 2, readConcern: { afterClusterTime: Timestamp(0, 1) }, $replData: 1, $oplogQueryData: 1, $readPreference: { mode: “secondaryPreferred” }, $clusterTime: { clusterTime: Timestamp(1667995888, 584), signature: { hash: BinData(0, 908904E7F425925423D0DA35F74D736722331DB9), keyId: 7150119648661340164 } }, $db: “local” } planSummary: COLLSCAN cursorid:3744042275538770656 keysExamined:0 docsExamined:3 numYields:1 nreturned:3 reslen:2082 locks:{ ReplicationStateTransition: { acquireCount: { w: 2 } }, Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 2 } }, Mutex: { acquireCount: { r: 1 } }, oplog: { acquireCount: { r: 2 } } } storage:{} protocol:op_msg 418ms

3

Hi @venkataraman_r and welcome to the MongoDB forum!!

for better understanding of the above error message, if would be very helpful if you could share the following details:

  1. The logs snipped shared, is from a Primary or a secondary node?

  1. What impact do you see on the performance while switching between the MongoDB versions.

  2. Is there a chance that you application is trying to read the oplogs from the server? There are some framework that does this by default (e.g. Meteor).

Best Regards
Aasawari

4

Hi Aasawari,

I see its happening on both Primary and Secondary. We dont read anything from oplog directly.

After we switched to mongodb4.2 (no changes from the client side as we uses compatible driver 3.12.9) , we see the query response is going crazy. We are trying to see what are the contributing factors and we see these queries are taking more time. Also we started to see IDHACK which suppose to be an optimized query that also taking mre time due to this.

/var/log/mongodb-27951.log:2022-11-16T04:37:35.348+0000 I COMMAND [conn8303] command local.oplog.rs command: getMore { getMore: 2277507442850471832, collection: "oplog.rs", batchSize: 13981010, maxTimeMS: 5000, term: 2, lastKnownCommittedOpTime: { ts: Timestamp(1668573449, 2688), t: 2 }, $replData: 1, $oplogQueryData: 1, $readPreference: { mode: "secondaryPreferred" }, $clusterTime: { clusterTime: Timestamp(1668573449, 2844), signature: { hash: BinData(0, 3D6BC62F737C84288EF8DC5062F68D70A314756B), keyId: 7166105568476659716 } }, $db: "local" } originatingCommand: { find: "oplog.rs", filter: { ts: { $gte: Timestamp(1668488972, 7) } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 60000, batchSize: 13981010, term: 2, readConcern: { afterClusterTime: Timestamp(0, 1) }, $replData: 1, $oplogQueryData: 1, $readPreference: { mode: "secondaryPreferred" }, $clusterTime: { clusterTime: Timestamp(1668488984, 2), signature: { hash: BinData(0, 052BE08BB97364A3B36D0B64AE8387624FD8D06E), keyId: 7166105568476659716 } }, $db: "local" } planSummary: COLLSCAN cursorid:2277507442850471832 keysExamined:0 docsExamined:66 numYields:6 nreturned:66 reslen:25336 locks:{ ReplicationStateTransition: { acquireCount: { w: 7 } }, Global: { acquireCount: { r: 7 } }, Database: { acquireCount: { r: 7 } }, Mutex: { acquireCount: { r: 1 } }, oplog: { acquireCount: { r: 7 } } } storage:{} protocol:op_msg 5553ms

/var/log/mongodb-37952.log:2022-11-16T04:38:30.433+0000 local.oplog.rs 593ms
/var/log/mongodb-37952.log:2022-11-16T04:38:30.432+0000 local.oplog.rs 593ms
/var/log/mongodb-37717.log:2022-11-16T04:39:48.082+0000 local.oplog.rs 590ms
/var/log/mongodb-27960.log:2022-11-16T04:34:41.634+0000 local.oplog.rs 1136ms
/var/log/mongodb-27960.log:2022-11-16T04:34:41.597+0000 local.oplog.rs 2794ms
/var/log/mongodb-27960.log:2022-11-16T04:34:41.592+0000 local.oplog.rs 2780ms
/var/log/mongodb-27960.log:2022-11-16T04:34:39.552+0000 local.oplog.rs 750ms
/var/log/mongodb-27959.log:2022-11-16T04:34:49.841+0000 local.oplog.rs 1700ms
/var/log/mongodb-27959.log:2022-11-16T04:34:47.917+0000 local.oplog.rs 2864ms
/var/log/mongodb-27959.log:2022-11-16T04:34:47.896+0000 local.oplog.rs 834ms
/var/log/mongodb-27959.log:2022-11-16T04:34:47.696+0000 local.oplog.rs 2645ms
/var/log/mongodb-27959.log:2022-11-16T04:34:44.543+0000 local.oplog.rs 731ms
/var/log/mongodb-27959.log:2022-11-16T04:34:44.538+0000 local.oplog.rs 728ms
/var/log/mongodb-27958.log:2022-11-16T04:32:17.638+0000 local.oplog.rs 556ms
/var/log/mongodb-27957.log:2022-11-16T04:38:30.430+0000 local.oplog.rs 590ms
/var/log/mongodb-27954.log:2022-11-16T04:34:41.534+0000 local.oplog.rs 2731ms
/var/log/mongodb-27954.log:2022-11-16T04:34:41.250+0000 local.oplog.rs 2446ms
/var/log/mongodb-27953.log:2022-11-16T04:38:54.832+0000 local.oplog.rs 760ms
/var/log/mongodb-27953.log:2022-11-16T04:38:54.816+0000 local.oplog.rs 744ms
/var/log/mongodb-27953.log:2022-11-16T04:36:43.602+0000 local.oplog.rs 921ms
/var/log/mongodb-27953.log:2022-11-16T04:36:43.598+0000 local.oplog.rs 917ms
/var/log/mongodb-27953.log:2022-11-16T04:36:43.584+0000 local.oplog.rs 903ms
/var/log/mongodb-27953.log:2022-11-16T04:34:49.867+0000 local.oplog.rs 1719ms
/var/log/mongodb-27953.log:2022-11-16T04:34:49.830+0000 local.oplog.rs 1682ms
/var/log/mongodb-27953.log:2022-11-16T04:34:49.830+0000 local.oplog.rs 1270ms
/var/log/mongodb-27952.log:2022-11-16T04:39:11.530+0000 local.oplog.rs 651ms
/var/log/mongodb-27952.log:2022-11-16T04:38:35.177+0000 local.oplog.rs 729ms
/var/log/mongodb-27952.log:2022-11-16T04:37:51.275+0000 local.oplog.rs 1193ms
/var/log/mongodb-27951.log:2022-11-16T04:38:30.438+0000 local.oplog.rs 598ms
/var/log/mongodb-27951.log:2022-11-16T04:37:35.348+0000 local.oplog.rs 5553ms
/var/log/mongodb-27737.log:2022-11-16T04:39:48.089+0000 local.oplog.rs 595ms
/var/log/mongodb-27737.log:2022-11-16T04:39:48.088+0000 local.oplog.rs 594ms
/var/log/mongodb-27737.log:2022-11-16T04:39:48.086+0000 local.oplog.rs 589ms
/var/log/mongodb-27730.log:2022-11-16T04:33:25.480+0000 local.oplog.rs 897ms
/var/log/mongodb-27730.log:2022-11-16T04:33:25.472+0000 local.oplog.rs 888ms ```