Oplog incremental backup failure

Question

I have scheduled oplog incremental dump using mongodump but it fails very often on majority of the servers. I have a shard cluster with around 200GB of oplog size defined and around 30-40 hours of oplog window.

I am thinking it is because of message "WiredTiger record store oplog truncation" just before the dump starts which is common during every failure. Other times, the dump runs perfectly fine. I have analysed the oplog window and size and it is fine. The oplog start data was way older than the timestamp I am using during oplog dump.

Below are some of the logs :

1. From mongod.log and my backup script :

2020-07-19T16:28:10.472+0000 I STORAGE  [WT RecordStoreThread: local.oplog.rs] WiredTiger record store oplog truncation finished in: 420ms

2020-07-19T16:28:10.502+0000 E QUERY    [conn74791] Plan executor error during find command: DEAD, stats: { stage: "COLLSCAN", filter: { $and: [ { ts: { $lte: Timestamp(1595176086, 2244) } }, { ts: { $gt: Timestamp(1595173520, 25) } } ] }, nReturned: 0, executionTimeMillisEstimate: 2970, works: 356598, advanced: 0, needTime: 356597, needYield: 0, saveState: 2787, restoreState: 2787, isEOF: 0, invalidates: 0, direction: "forward", docsExamined: 356596 }```

oplog-prd-mon-bzm-shard-hd03.c.blazemeter-dr.internal-20200719.log-2020-07-19T16:28:06.794+0000 reading password from standard input
oplog-prd-mon-bzm-shard-hd03.c.blazemeter-dr.internal-20200719.log-Enter password:
oplog-prd-mon-bzm-shard-hd03.c.blazemeter-dr.internal-20200719.log-2020-07-19T16:28:07.153+0000 writing local.oplog.rs to stdout
oplog-prd-mon-bzm-shard-hd03.c.blazemeter-dr.internal-20200719.log-2020-07-19T16:28:09.795+0000 local.oplog.rs  0
oplog-prd-mon-bzm-shard-hd03.c.blazemeter-dr.internal-20200719.log-2020-07-19T16:28:10.517+0000 local.oplog.rs  0
oplog-prd-mon-bzm-shard-hd03.c.blazemeter-dr.internal-20200719.log:2020-07-19T16:28:10.517+0000 Failed: error writing data for collection `local.oplog.rs` to disk: error reading collection: Executor error during find command :: caused by :: errmsg: "CollectionScan died due to position in capped collection being deleted. Last seen record id: RecordId(6850019249918838732)"

Answer 1

You are right, the oplog truncation is killing your cursor.

There are no indexes on the oplog, so dump has to scan from the very beginning to find the documents that match the query.

In that case of this mongodump cursor, it had examined 356596 documents, but still hadn't found any that matched the query.

The failure message reports the last seen record was "RecordId(6850019249918838732)". That number is a 64-bit value that corresponds to the ts.

You can get the first 32 bits and the corresponding timestamp from bash:

% echo $((6850019249918838732 >> 32))
1594894391

That date is Thu Jul 16 10:13:11 UTC 2020 still over a month prior to the first date of interest.

When those documents were trimmed from the capped collection, the cursor no longer pointed to a valid position, so it was not possible to continue.

When that happens, you'll need to restart the mongodump so it can start scanning from the new beginning of the oplog.

Answer 2

Thank you so much for this helpful insights. I want to add few more thing like below.

As of now we are mitigating this issue by retrying the mongodump after certain failures but it doesn't seems like an optimal approach. We have even tried increasing WT cache, eviction threads, triggers and dirty ratio but no help.

We can't understand why the "mongodump" looking for older timestamp than "tFirst" of oplog.

Below are the recent failure logs.

1. From our backup script :

2020-09-17T11:03:05.475+0000 E QUERY [conn995798] Plan executor error during find command: DEAD, stats: { stage: "COLLSCAN", filter: { $and: [ { ts: { $lte: Timestamp(1600340581, 1413) } }, { ts: { $gt: Timestamp(1600335989, 5722) } } ] }, nReturned: 0, executionTimeMillisEstimate: 2900, works: 54234, advanced: 0, needTime: 54233, needYield: 0, saveState: 430, restoreState : 430, isEOF: 0, invalidates: 0, direction: "forward", docsExamined: 54232 }

2. Mongo logs :

 [blazemeter] percona@prd-mon-bzm-shard-hd02: mongodb $ sudo grep -m 3 -B 5 'DEAD' mongodb.log
2020-09-17T10:25:47.271+0000 I NETWORK  [conn995231] received client metadata from 10.100.0.98:54928 conn995231: { driver: { name:

"PyMongo", version: "3.4.0" }, os: { type: "Linux", name: "CentOS Linux 7.7.1908 Core", architecture: "x86_64", version: "3.10.0-1062.18.1.el7.x86_64" }, platform: "CPython 2.7.5.final.0" } 2020-09-17T10:25:47.380+0000 I ACCESS [conn995231] Successfully authenticated as principal pmonuser on admin from client 10.100.0.98:54928 2020-09-17T10:25:47.505+0000 I STORAGE [WT RecordStoreThread: local.oplog.rs] WiredTiger record store oplog truncation finished in: 239ms 2020-09-17T10:25:47.510+0000 I NETWORK [conn995230] end connection 10.100.0.98:54926 (14 connections now open) 2020-09-17T10:25:47.510+0000 I NETWORK [conn995231] end connection 10.100.0.98:54928 (13 connections now open) 2020-09-17T10:25:47.537+0000 E QUERY [conn995226] Plan executor error during find command: DEAD, stats: { stage: "COLLSCAN", filter: { $and: [ { ts: { $lte: Timestamp(1600338342, 195) } }, { ts: { $gt: Timestamp(1600335989, 5722) } } ] }, nReturned: 0, executionTimeMillisEstimate: 4590, works: 385676, advanced: 0, needTime: 385675, needYield: 0, saveState: 3015, restoreState: 3015, isEOF: 0, invalidates: 0, direction: "forward", docsExamined: 385674 }

--

2020-09-17T11:03:02.342+0000 I ACCESS   [conn995799] Successfully authenticated as principal pmonuser on admin from client

10.100.0.98:43326 2020-09-17T11:03:03.013+0000 I NETWORK [listener] connection accepted from 127.0.0.1:49168 #995800 (13 connections now open) 2020-09-17T11:03:03.013+0000 I NETWORK [conn995800] received client metadata from 127.0.0.1:49168 conn995800: { driver: { name: "mongo-go-driver", version: "v1.3.2" }, os: { type: "linux", architecture: "amd64" }, platform: "go1.13.10", application: { name: "QAN-mongodb-profiler-/agent_id/5c0d2b03-eedd-4124-abda-ee6cea3cd48e" } } 2020-09-17T11:03:03.022+0000 I ACCESS [conn995800] Successfully authenticated as principal pmonuser on admin from client 127.0.0.1:49168 2020-09-17T11:03:05.421+0000 I STORAGE [WT RecordStoreThread: local.oplog.rs] WiredTiger record store oplog truncation finished in: 389ms 2020-09-17T11:03:05.475+0000 E QUERY [conn995798] Plan executor error during find command: DEAD, stats: { stage: "COLLSCAN", filter: { $and: [ { ts: { $lte: Timestamp(1600340581, 1413) } }, { ts: { $gt: Timestamp(1600335989, 5722) } } ] }, nReturned: 0, executionTimeMillisEstimate: 2900, works: 54234, advanced: 0, needTime: 54233, needYield: 0, saveState: 430, restoreState: 430, isEOF: 0, invalidates: 0, direction: "forward", docsExamined: 54232

}

3. Oplog window :

Prod-Shard_2:SECONDARY> db.getReplicationInfo()

{ "logSizeMB" : 250000, "usedMB" : 248310.45, "timeDiff" : 135740, "timeDiffHours" : 37.71, "tFirst" : "Tue Sep 15 2020 21:28:10 GMT+0000 (UTC)", "tLast" : "Thu Sep 17 2020 11:10:30 GMT+0000 (UTC)", "now" : "Thu Sep 17 2020 11:10:30 GMT+0000 (UTC)" }

4. Converted timestamp :

[blazemeter] percona@bzm-monitor: backups $ echo $((6872826050246617646 >> 32)) 1600204513 [blazemeter] percona@bzm-monitor: backups $ date -d@1600204513 Tue Sep 15 21:15:13 UTC 2020

We can't understand why "RecordId" is less than that of "tFirst" in oplog even though we are running oplog dump with higher timestamps. I understand that it scan entire oplog but why is it looking for the timestamp which is already gone ? Does mongodump placing a marker (RecordId) where it looks for older timestamp even after oldest documents truncated hence fails ?