1

Using single instance MongoDB v4.2.0 on Debian 9.11 with collection of 78GB and 60M documents on a 2 vCPUs, 13 GB memory server. This command is invoked on the same server where database runs:

mongodump --username user --password pwd --authenticationDatabase admin --host localhost --gzip --archive=out.gz --db database --collection collection

And after 10 minutes this is the output:

2019-10-17T16:13:09.523+0200    Failed: error creating intents to
dump: error counting database.collection:
connection(localhost:27017[-2]) unable to decode message length: read
tcp 127.0.0.1:57798->127.0.0.1:27017: i/o timeout

By looking at mongod.log this is what mongodump outputs:

2019-10-17T16:13:09.523+0200 I  NETWORK  [conn20] end connection 127.0.0.1:57794 (4 connections now open)
2019-10-17T16:13:09.748+0200 I  -        [conn21] operation was interrupted because a client disconnected
2019-10-17T16:13:10.371+0200 W  COMMAND  [conn21] Unable to gather storage statistics for a slow operation due to lock aquire timeout
2019-10-17T16:13:10.371+0200 I  COMMAND  [conn21] command database.collection appName: "mongodump" command: aggregate { aggregate: "collection",
pipeline: [ { $match: {} }, { $group: { _id: 1, n: { $sum: 1 } } } ], cursor: {}, lsid: { id: UUID("4759f9ad-7d37-44c7-bd41-8610af565c47") },
$db: "database" } planSummary: COLLSCAN numYields:437454 ok:0 errMsg:"Error in $cursor stage :: caused by :: operation was interrupted because
a client disconnected" errName:ClientDisconnect errCode:279 reslen:186 locks:{ ReplicationStateTransition: { acquireCount: { w: 437456 } },
Global: { acquireCount: { r: 437456 } }, Database: { acquireCount: { r: 437455 } }, Collection: { acquireCount: { r: 437455 } }, Mutex: {
acquireCount: { r: 2 } } } protocol:op_msg 600852ms

It looks like mongodump internally runs this aggregate query:

[ { $match: {} }, { $group: { _id: 1, n: { $sum: 1 } } } ]

And when the same query is run from MongoDB shell it works:

> db.collection.aggregate([ { $match: {} }, { $group: { _id: 1, n: { $sum: 1 } } } ])
{ "_id" : 1, "n" : 60488853 }

And this is the mongod.log output:

2019-10-17T15:01:37.130+0200 I  COMMAND  [conn2] command database.collection  appName: "MongoDB Shell" command: aggregate
{ aggregate: "collection", pipeline: [ { $match: {} }, { $group: { _id: 1.0, n: { $sum: 1.0 } } } ], cursor: {}, lsid: {
id: UUID("3b732623-e8b4-4365-bac7-efa710db035c") }, $db: "database" } planSummary: COLLSCAN keysExamined:0
docsExamined:60488853 cursorExhausted:1 numYields:472591 nreturned:1 reslen:136 locks:{ ReplicationStateTransition: {
acquireCount: { w: 472593 } }, Global: { acquireCount: { r: 472593 } }, Database: { acquireCount: { r: 472593 } },
Collection: { acquireCount: { r: 472593 } }, Mutex: { acquireCount: { r: 2 } } } storage:{ data: { bytesRead: 79320933249,
timeReadingMicros: 610249624 } } protocol:op_msg 653559ms

What can be seen is that this count query from shell takes 653 seconds while the mongodump internal query timeouts after 600 seconds (10 minutes exactly).

Other smaller collections and databases on the same server do not have this issue, just this large one.

How this timeout or issue for large queries can be solved so that mongodump runs without issues?

1

It looks like there was a bug as after upgrading to MongoDB v4.2.1 the issue does not happen any more.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.