Node connector v5 much slower than v3.2.7

Hello there. I am upgrading from node connector 3.2.7 to 5.0.x.
My mongo server is on 6.0.4. My node version is v18.13.0.

On a moderately large query, the new connector is considerably slower.

Below I have include…

  • the code
  • the results (empirically around 1.6 times longer with the newer driver over multiple runs).
  • the logs (perhaps suggesting latency at the client between getMore calls: ~20ms rather than ~10ms)

Is there some new connection or query parameters that I should be using, perhaps?
Many thanks!


Code

MONGO_URL = 'mongodb://xxxx:yyyyyy!@0.0.0.0/zzzz';
const { MongoClient } = require('mongodb');
(async () => {
  const client = await MongoClient.connect(MONGO_URL, { useNewUrlParser: true });
  const db = await client.db();
  const audit = db.collection('Audit');
  const start = Date.now();
  const count = (await audit.find().toArray()).length;
  console.log(Date.now() - start, 'ms', count, 'recs');
})();

V3.2.7 Results
154 ms 11196 recs

V5.0.1 Results
248 ms 11196 recs


V3.2.7 logs

{"t":{"$date":"2023-05-19T18:11:16.189+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"172.17.0.1:34096","uuid":"77810513-8218-4bd2-8c76-7f6dc494e062","connectionId":11,"connectionCount":1}}
{"t":{"$date":"2023-05-19T18:11:16.191+00:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn11","msg":"client metadata","attr":{"remote":"172.17.0.1:34096","client":"conn11","doc":{"driver":{"name":"nodejs","version":"3.2.7"},"os":{"type":"Linux","name":"linux","architecture":"arm64","version":"5.15.49-linuxkit"},"platform":"Node.js v18.13.0, LE, mongodb-core: 3.2.7"}}}
{"t":{"$date":"2023-05-19T18:11:16.191+00:00"},"s":"D1", "c":"ACCESS",   "id":20226,   "ctx":"conn11","msg":"Returning user from cache","attr":{"user":{"user":"peek","db":"peek"}}}
{"t":{"$date":"2023-05-19T18:11:16.194+00:00"},"s":"D1", "c":"ACCESS",   "id":20226,   "ctx":"conn11","msg":"Returning user from cache","attr":{"user":{"user":"peek","db":"peek"}}}
{"t":{"$date":"2023-05-19T18:11:16.194+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"peek.$cmd","command":{"saslStart":1,"mechanism":"SCRAM-SHA-256","payload":"xxx","autoAuthorize":1,"$db":"peek"},"numYields":0,"reslen":211,"locks":{},"authorization":{"startedUserCacheAcquisitionAttempts":1,"completedUserCacheAcquisitionAttempts":1,"userCacheWaitTimeMicros":2},"remote":"172.17.0.1:34096","protocol":"op_query","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:11:16.198+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"peek.$cmd","command":{"saslContinue":1,"conversationId":1,"payload":"xxx","$db":"peek"},"numYields":0,"reslen":140,"locks":{},"remote":"172.17.0.1:34096","protocol":"op_query","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:11:16.199+00:00"},"s":"D1", "c":"ACCESS",   "id":20226,   "ctx":"conn11","msg":"Returning user from cache","attr":{"user":{"user":"peek","db":"peek"}}}
{"t":{"$date":"2023-05-19T18:11:16.199+00:00"},"s":"I",  "c":"ACCESS",   "id":20250,   "ctx":"conn11","msg":"Authentication succeeded","attr":{"mechanism":"SCRAM-SHA-256","speculative":false,"principalName":"peek","authenticationDatabase":"peek","remote":"172.17.0.1:34096","extraInfo":{}}}
{"t":{"$date":"2023-05-19T18:11:16.199+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"peek.$cmd","command":{"saslContinue":1,"conversationId":1,"payload":"xxx","$db":"peek"},"numYields":0,"reslen":94,"locks":{},"authorization":{"startedUserCacheAcquisitionAttempts":1,"completedUserCacheAcquisitionAttempts":1,"userCacheWaitTimeMicros":2},"remote":"172.17.0.1:34096","protocol":"op_query","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:11:16.204+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"find":"Audit","filter":{},"returnKey":false,"showRecordId":false,"$db":"peek"},"planSummary":"COLLSCAN","cursorid":7259635789622636012,"keysExamined":0,"docsExamined":101,"numYields":0,"nreturned":101,"queryHash":"17830885","queryFramework":"classic","reslen":37956,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":1}},"Global":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:34096","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:11:16.208+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":7259635789622636012,"collection":"Audit","batchSize":1000,"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"returnKey":false,"showRecordId":false,"$db":"peek"},"planSummary":"COLLSCAN","cursorid":7259635789622636012,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":442742,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:34096","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:11:16.227+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":7259635789622636012,"collection":"Audit","batchSize":1000,"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"returnKey":false,"showRecordId":false,"$db":"peek"},"planSummary":"COLLSCAN","cursorid":7259635789622636012,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":463903,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:34096","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:11:16.237+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":7259635789622636012,"collection":"Audit","batchSize":1000,"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"returnKey":false,"showRecordId":false,"$db":"peek"},"planSummary":"COLLSCAN","cursorid":7259635789622636012,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":443412,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:34096","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:11:16.255+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":7259635789622636012,"collection":"Audit","batchSize":1000,"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"returnKey":false,"showRecordId":false,"$db":"peek"},"planSummary":"COLLSCAN","cursorid":7259635789622636012,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":482736,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:34096","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:11:16.266+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":7259635789622636012,"collection":"Audit","batchSize":1000,"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"returnKey":false,"showRecordId":false,"$db":"peek"},"planSummary":"COLLSCAN","cursorid":7259635789622636012,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":485793,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:34096","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:11:16.276+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":7259635789622636012,"collection":"Audit","batchSize":1000,"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"returnKey":false,"showRecordId":false,"$db":"peek"},"planSummary":"COLLSCAN","cursorid":7259635789622636012,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":475154,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:34096","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:11:16.286+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":7259635789622636012,"collection":"Audit","batchSize":1000,"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"returnKey":false,"showRecordId":false,"$db":"peek"},"planSummary":"COLLSCAN","cursorid":7259635789622636012,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":516914,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:34096","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:11:16.299+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":7259635789622636012,"collection":"Audit","batchSize":1000,"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"returnKey":false,"showRecordId":false,"$db":"peek"},"planSummary":"COLLSCAN","cursorid":7259635789622636012,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":526351,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:34096","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:11:16.309+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":7259635789622636012,"collection":"Audit","batchSize":1000,"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"returnKey":false,"showRecordId":false,"$db":"peek"},"planSummary":"COLLSCAN","cursorid":7259635789622636012,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":525263,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:34096","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:11:16.321+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":7259635789622636012,"collection":"Audit","batchSize":1000,"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"returnKey":false,"showRecordId":false,"$db":"peek"},"planSummary":"COLLSCAN","cursorid":7259635789622636012,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":508402,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:34096","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:11:16.331+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":7259635789622636012,"collection":"Audit","batchSize":1000,"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"returnKey":false,"showRecordId":false,"$db":"peek"},"planSummary":"COLLSCAN","cursorid":7259635789622636012,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":452847,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:34096","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:11:16.351+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn11","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":7259635789622636012,"collection":"Audit","batchSize":1000,"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"returnKey":false,"showRecordId":false,"$db":"peek"},"planSummary":"COLLSCAN","cursorid":7259635789622636012,"keysExamined":0,"docsExamined":95,"cursorExhausted":true,"numYields":0,"nreturned":95,"queryHash":"17830885","reslen":41793,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":1}},"Global":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:34096","protocol":"op_msg","durationMillis":0}}

V5.0.1 logs

{"t":{"$date":"2023-05-19T18:05:08.374+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"172.17.0.1:36362","uuid":"6d25fb37-6878-4ea0-a0ed-e6496619c659","connectionId":2,"connectionCount":1}}
{"t":{"$date":"2023-05-19T18:05:08.376+00:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn2","msg":"client metadata","attr":{"remote":"172.17.0.1:36362","client":"conn2","doc":{"driver":{"name":"nodejs","version":"5.5.0"},"platform":"Node.js v18.13.0, LE","os":{"name":"linux","architecture":"arm64","version":"5.15.49-linuxkit","type":"Linux"}}}}
{"t":{"$date":"2023-05-19T18:05:08.379+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"Connection accepted","attr":{"remote":"172.17.0.1:36368","uuid":"c97a3041-4b94-45a1-ae8e-a2d74d80acaf","connectionId":3,"connectionCount":2}}
{"t":{"$date":"2023-05-19T18:05:08.381+00:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn3","msg":"client metadata","attr":{"remote":"172.17.0.1:36368","client":"conn3","doc":{"driver":{"name":"nodejs","version":"5.5.0"},"platform":"Node.js v18.13.0, LE","os":{"name":"linux","architecture":"arm64","version":"5.15.49-linuxkit","type":"Linux"}}}}
{"t":{"$date":"2023-05-19T18:05:08.381+00:00"},"s":"D1", "c":"ACCESS",   "id":20226,   "ctx":"conn3","msg":"Returning user from cache","attr":{"user":{"user":"peek","db":"peek"}}}
{"t":{"$date":"2023-05-19T18:05:08.381+00:00"},"s":"D1", "c":"ACCESS",   "id":20226,   "ctx":"conn3","msg":"Returning user from cache","attr":{"user":{"user":"peek","db":"peek"}}}
{"t":{"$date":"2023-05-19T18:05:08.387+00:00"},"s":"D1", "c":"ACCESS",   "id":20226,   "ctx":"conn3","msg":"Returning user from cache","attr":{"user":{"user":"peek","db":"peek"}}}
{"t":{"$date":"2023-05-19T18:05:08.387+00:00"},"s":"I",  "c":"ACCESS",   "id":20250,   "ctx":"conn3","msg":"Authentication succeeded","attr":{"mechanism":"SCRAM-SHA-256","speculative":true,"principalName":"peek","authenticationDatabase":"peek","remote":"172.17.0.1:36368","extraInfo":{}}}
{"t":{"$date":"2023-05-19T18:05:08.387+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn3","msg":"Slow query","attr":{"type":"command","ns":"peek.$cmd","command":{"saslContinue":1,"conversationId":1,"payload":"xxx","$db":"peek"},"numYields":0,"reslen":125,"locks":{},"authorization":{"startedUserCacheAcquisitionAttempts":1,"completedUserCacheAcquisitionAttempts":1,"userCacheWaitTimeMicros":2},"remote":"172.17.0.1:36368","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:05:08.392+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn3","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"find":"Audit","filter":{},"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"planSummary":"COLLSCAN","cursorid":104885741916121744,"keysExamined":0,"docsExamined":101,"numYields":0,"nreturned":101,"queryHash":"17830885","queryFramework":"classic","reslen":37956,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":1}},"Global":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:36368","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:05:08.399+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn3","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":104885741916121744,"collection":"Audit","batchSize":1000,"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"planSummary":"COLLSCAN","cursorid":104885741916121744,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":442742,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:36368","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:05:08.430+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn3","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":104885741916121744,"collection":"Audit","batchSize":1000,"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"planSummary":"COLLSCAN","cursorid":104885741916121744,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":463903,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:36368","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:05:08.459+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn3","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":104885741916121744,"collection":"Audit","batchSize":1000,"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"planSummary":"COLLSCAN","cursorid":104885741916121744,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":443412,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:36368","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:05:08.478+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn3","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":104885741916121744,"collection":"Audit","batchSize":1000,"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"planSummary":"COLLSCAN","cursorid":104885741916121744,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":482736,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:36368","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:05:08.495+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn3","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":104885741916121744,"collection":"Audit","batchSize":1000,"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"planSummary":"COLLSCAN","cursorid":104885741916121744,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":485793,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:36368","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:05:08.512+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn3","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":104885741916121744,"collection":"Audit","batchSize":1000,"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"planSummary":"COLLSCAN","cursorid":104885741916121744,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":475154,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:36368","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:05:08.534+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn3","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":104885741916121744,"collection":"Audit","batchSize":1000,"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"planSummary":"COLLSCAN","cursorid":104885741916121744,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":516914,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:36368","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:05:08.555+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn3","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":104885741916121744,"collection":"Audit","batchSize":1000,"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"planSummary":"COLLSCAN","cursorid":104885741916121744,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":526351,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:36368","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:05:08.581+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn3","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":104885741916121744,"collection":"Audit","batchSize":1000,"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"planSummary":"COLLSCAN","cursorid":104885741916121744,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":525263,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:36368","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:05:08.602+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn3","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":104885741916121744,"collection":"Audit","batchSize":1000,"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"planSummary":"COLLSCAN","cursorid":104885741916121744,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":508402,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:36368","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:05:08.619+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn3","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":104885741916121744,"collection":"Audit","batchSize":1000,"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"planSummary":"COLLSCAN","cursorid":104885741916121744,"keysExamined":0,"docsExamined":1000,"numYields":1,"nreturned":1000,"queryHash":"17830885","reslen":452847,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":2}},"Global":{"acquireCount":{"r":2}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:36368","protocol":"op_msg","durationMillis":0}}
{"t":{"$date":"2023-05-19T18:05:08.636+00:00"},"s":"I",  "c":"COMMAND",  "id":51803,   "ctx":"conn3","msg":"Slow query","attr":{"type":"command","ns":"peek.Audit","command":{"getMore":104885741916121744,"collection":"Audit","batchSize":1000,"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"originatingCommand":{"find":"Audit","filter":{},"lsid":{"id":{"$uuid":"2673876e-e4b2-4c6b-bb05-4fcb06845ab3"}},"$db":"peek"},"planSummary":"COLLSCAN","cursorid":104885741916121744,"keysExamined":0,"docsExamined":95,"cursorExhausted":true,"numYields":0,"nreturned":95,"queryHash":"17830885","reslen":41793,"locks":{"FeatureCompatibilityVersion":{"acquireCount":{"r":1}},"Global":{"acquireCount":{"r":1}},"Mutex":{"acquireCount":{"r":1}}},"storage":{},"remote":"172.17.0.1:36368","protocol":"op_msg","durationMillis":0}}

The behaviour is not improved by upgrade to 5.5.0

The biggest drop in performance I have found is with the introduction of V4/

Hi @Richard_Evans and welcome to MongoDB community forums!!

Based on the above sample code shared, I tried to replicate in my local environment by switching between versions 3.3.7, 5.0.0 and 5.5.0.

Below are the results for different connector versions:

Node JS version 3.2.7: ~10 ms
Node JS version 5.0.1: ~9.48 ms
Node JS version 5.5.0: ~9.48 ms

The above execution time is calculated based on multiple (~20 ) times execution of the similar query to read the data from the database and tried tested with multiple connector versions.

In order to understand concern more clearly and help you with relevant solutions if possible, could you help me with some details regarding the deployment.

  1. The architecture of the deployment, i.e standalone, replica set, sharded cluster.
  2. Is this architecture deployed on Atlas ? If yes, please go through the documentation on Analyse Slow Queries to analyse which query would be causing the performance degrade.

When you mention this, what is meant by large query? Are you targeting large number of collections or the query involves multiple complicated stages?
4. Is there index defined in the for the documents ?
5. Can you share the explain output for the query in all different versions?
6. Can you also confirm, if with this upgrade process, there was some change made in the application code which would impact the performance.

Regards
Aasawari

Thank you very much for looking into this, Aasawari!

My database server is running locally. Both node client and mongodb server are running in docker containers on my MacBook Pro. The difference has been reproduced on a colleague’s machine with a similar setup.

I notice your timings are very small, suggesting a small dataset. It material that the query returns a fairly large amount of data (a few thousand documents). If I look at the mongo logs, the v5 client calls getMore every 20ms whereas the V3 client calls more or less twice as fast.

I confess I have NOT checked whether the complexity of the documents is material. My documents have a nested structure averaging around 0.5k each.

Thanks again,
Richard

Hello again, Aasawari.

The collection has indices but the query is {} - so no predicates.
The query and the explain are in the logs above (line 10 of each version)
There was no change in the code, which is included in my original query.

Thanks!

Hello Aasawari. Were you able to make any progress with this?

Hi @Richard_Evans

Apologies for the delay in response.

It would be helpful if you share some additional details for the deployment.

  1. The query that you are trying to execute.
  2. A sample data with any sensitive data redacted.
  3. The output for db.collection.stats()
  4. The output for db.collection.explain(‘executionStats’).find({…}).

Regards
Aasawari

1 Like

I just saw this thread.

The following is absolutely the worst way to get the number of documents in a collection.

Can’t you use count() or countDocuments(), an aggregation with $count? If not, you could at least use a projection to only send the _id field over the wire.

Thanks @steevej . Sure. I realise that. The point of the ticket is that the paging of the documents is much slower in the current connector than it used to be so I need to retrieve the documents to show this. Audit.find().toArray() was simple code to reproduce the problem. I output the length just as evidence of the size of the retrieval.

@Aasawari - Sorry - I had not seen your response, thanks. Some of the information you have asked for is in the original ticket audit trail (the query was {} and the explain is in the verbose log). I will come back to this later with a line or two to populate the collection.)

Hello again. Here this is a slightly longer script which generates its own data in a collection called peekTestData. Note the collection is new and has no indices (other than the default _id). The documents are large but very simple.

All I do is find() with no constraint so retrieve all documents. The same v6.04 database is used in both tests. On my box the query runs slower with the new driver. It really does look as if the new driver just pages through data significantly more slowly

For V3.2.7 ~ 77 ms.
For V5.0.1 ~ 148 ms.

MONGO_URL = 'mongodb://insert-your-url';
const { MongoClient } = require('mongodb');
const collectionName = 'peekTestData';
const count = 10000;

(async () => {
  console.log('CONNECTING...');
  const client = await MongoClient.connect(MONGO_URL, { useNewUrlParser: true });
  console.log('CONNECTED');
  const db = await client.db();
  const collection = db.collection(collectionName);

  try {
    await collection.drop();
  } catch (e) {
  }

  let _id = 0;
  await collection.insertMany(new Array(count).fill({}).map(() => ({ _id: _id++, text })));
  const start = Date.now();
  const found = (await collection.find().toArray()).length;
  console.log(Date.now() - start, found);
  process.exit(0);
})();

const text = `"Lorem ipsum dolor sit amet, consectetur adipiscing elit. Fusce quis tristique lacus, nec dictum sapien. Nunc rutrum ligula a efficitur lacinia. Sed sit amet pulvinar sapien, ac feugiat enim. Aliquam ultrices lectus vitae sollicitudin tincidunt. Nulla facilisi. Morbi condimentum ipsum et tortor commodo, sed convallis purus efficitur. Sed tristique pellentesque eros, eu interdum elit vestibulum eu. Praesent varius velit vel ex varius, sed auctor justo elementum. Cras tempor lectus eu risus finibus, eget auctor metus ullamcorper. Vestibulum ante ipsum primis in faucibus orci luctus et ultrices posuere cubilia curae; Proin facilisis risus ut justo rutrum, vitae maximus massa hendrerit. Aenean non arcu nec justo interdum cursus a a sem. Curabitur tristique nisl at dolor scelerisque, eu venenatis velit varius. Fusce vel lorem ac massa dictum malesuada. Suspendisse potenti.
Sed eu gravida velit, sit amet auctor lorem. Nam sagittis tincidunt orci, vitae hendrerit leo dictum non. Mauris vitae lacinia orci, eu tincidunt ex. Integer sed interdum quam. Suspendisse a risus feugiat, commodo orci id, lobortis lacus. Donec vestibulum auctor semper. Sed ut urna id lacus elementum viverra eu quis sapien. Suspendisse rhoncus ante vitae vulputate rutrum. Etiam sed tempor libero, sed lobortis justo. Vestibulum accumsan condimentum odio, non condimentum lectus pharetra id. Morbi nec malesuada sapien. Fusce sodales mauris eu eros dignissim finibus. Aenean ac orci ullamcorper, commodo tortor eget, consectetur mauris. Nullam vehicula augue sit amet tellus elementum, at dapibus ipsum dapibus. Morbi pulvinar libero vel eros fringilla, eget tincidunt nisl luctus. Ut ullamcorper mi sed est congue, sit amet hendrerit velit venenatis.
Vivamus in leo sed massa interdum finibus. Nunc vitae ligula fringilla, cursus turpis nec, lacinia mi. Mauris interdum nibh ut dui laoreet, id eleifend risus volutpat. Integer rhoncus justo et nisi efficitur, ut tempus neque ultrices. Aliquam in est sit amet tellus hendrerit gravida vitae et massa. Phasellus sed justo eget diam varius viverra. Sed sed neque tristique, hendrerit mauris eget, placerat elit. Integer bibendum justo vitae fermentum consequat. Pellentesque nec ex tincidunt, consequat turpis id, lacinia dolor. Sed hendrerit turpis eu dui fermentum, id semper arcu interdum. Nulla facilisi. Suspendisse quis tellus quis felis gravida tempor.
Pellentesque nec feugiat diam. Suspendisse potenti. Morbi ac iaculis odio. Sed lacinia posuere odio, at dignissim elit auctor in. Mauris consequat velit eu velit feugiat condimentum. Sed non ne`;

Like I already mentioned

is the worst way to get document counts. It is a waste of time to try to understand why it is slower.

If the issue is your

then it is the code you need to share. Both your paging and collection.find.toArray might be slower but it does not mean it is for the same reason. And the solution is probably different.

Thanks for chipping in here. @steevej . As I said, I am very aware that this is not a sensible way to do a count. No need to explain! However my question is about the fact that “await collection.find().toArray()” is much slower on the new connector. Just ignore the .length if it helps. In real life I’d do something useful with the results but that would distract from this question.

Under the scenes the connector retrieves a large query in batches. If you look at the log for my original ticket, you can see this happening. The frequency of the paging has become much lower since 3.2.7. Put another way, queries for large datasets are much slower in the current version of the connector.