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?
