I am trying to figure out the latency issue I was having when connecting with MongoClient with node.js when running on AWS Lambda. I am using the v5.1 driver. Here is the setup:
The test collection is one of around 10 documents of the following format without indexing
{
"_id": {
"$oid": "65b220e9fc6dd8352013c860"
},
"email": "1234@1234.com"
}
Querying takes sub milliseconds on Compass. I have followed some of the guidelines and made sure the MongoClient instance is static on the AWS. To ensure I am always running the same Lambda instance I enabled provision concurrency. The test code performs one find query and returns immediately. Some of the logging statements are omitted.
const MongoClient = require('mongodb').MongoClient;
const client = new MongoClient(...);
var db = null;
client.on("connectionPoolReady", (event) =>
console.log("connectionPoolReady:\n", event)
);
...
exports.handler = async (event, context) => {
context.callbackWaitsForEmptyEventLoop = false;
if (!db) {
db = await client.db(mongoDbName);
}
let timestamp = Date.now();
let result = await db.collection("UserId").find({ email: "1234@1234.com" }).toArray();
console.log(`collection.find(() took: ${Date.now() - timestamp}`);
...
return response;
};
Here is what I am seeing from the logs. The first load understandably took some time with the initiation of the driver. It took almost 2 seconds to finish the function.
2024-04-04T19:38:59.607-07:00 START RequestId: 33c8b095-818d-43d3-8af5-e56e444f599e Version: 4
2024-04-04T19:39:00.453-07:00 INFO connectionPoolReady: ConnectionPoolReadyEvent { time: 2024-04-05T02:39:00.453Z, address: ‘…’ }
2024-04-04T19:39:00.812-07:00 INFO connectionPoolReady: ConnectionPoolReadyEvent { time: 2024-04-05T02:39:00.812Z, address: ‘…’ }
2024-04-04T19:39:00.870-07:00 INFO connectionCheckOutStarted: ConnectionCheckOutStartedEvent { time: 2024-04-05T02:39:00.870Z, address: ‘…’ }
2024-04-04T19:39:00.871-07:00 INFO connectionCreated: ConnectionCreatedEvent { time: 2024-04-05T02:39:00.871Z, address: ‘…’, connectionId: 1 }
2024-04-04T19:39:00.911-07:00 INFOconnectionPoolReady: ConnectionPoolReadyEvent { time: 2024-04-05T02:39:00.911Z, address: ‘…’ }
2024-04-04T19:39:01.291-07:00 INFO connectionReady: ConnectionReadyEvent { time: 2024-04-05T02:39:01.291Z, address: ‘…‘, connectionId: 1 }
2024-04-04T19:39:01.292-07:00 INFO connectionCheckedOut: ConnectionCheckedOutEvent { time: 2024-04-05T02:39:01.292Z, address: ‘…’, connectionId: 1 }
2024-04-04T19:39:01.352-07:00 INFO connectionCheckedIn: ConnectionCheckedInEvent { time: 2024-04-05T02:39:01.352Z, address: ‘…', connectionId: 1 }
2024-04-04T19:39:01.353-07:00 INFO collection.find(() took: 1561
2024-04-04T19:39:01.412-07:00 END RequestId: 33c8b095-818d-43d3-8af5-e56e444f599e
2024-04-04T19:39:01.412-07:00 REPORT RequestId: 33c8b095-818d-43d3-8af5-e56e444f599eDuration: 1805.16 msBilled Duration: 1806 msMemory Size: 128 MBMax Memory Used: 82 MBInit Duration: 5423.45 ms
On immediate subsequent runs, it’s generally quite fast. The only events expectedly are checkouts of connectionsl.
2024-04-04T19:39:24.933-07:00 START RequestId: 289c6c4d-f364-4290-b74f-e92102fa9217 Version: 4
2024-04-04T19:39:25.031-07:00 INFO connectionCheckOutStarted: ConnectionCheckOutStartedEvent { time: 2024-04-05T02:39:25.031Z, address: ‘…’ }
2024-04-04T19:39:25.031-07:00 INFO connectionCheckedOut: ConnectionCheckedOutEvent { time: 2024-04-05T02:39:25.031Z, address: ‘…‘, connectionId: 1 }
2024-04-04T19:39:25.051-07:00 INFO connectionCheckedIn: ConnectionCheckedInEvent { time: 2024-04-05T02:39:25.051Z, address: ‘…’, connectionId: 1 }
2024-04-04T19:39:25.052-07:00 INFO collection.find(() took: 78
2024-04-04T19:39:25.071-07:00 END RequestId: 289c6c4d-f364-4290-b74f-e92102fa9217
2024-04-04T19:39:25.071-07:00 REPORT RequestId: 289c6c4d-f364-4290-b74f-e92102fa9217Duration: 137.44 msBilled Duration: 138 msMemory Size: 128 MBMax Memory Used: 82 MB
This call from 4 minutes after the first call above, against the same Lambda instance, took around 1 second. I noticed that the connectionCheckOutStarted is taking longer. The find() call itself still took less than the initial call. What is happening and how can this be fixed? Is this due to timeout of connections? How can I ensure a pool of readily usable connections that doesn’t require lengthy reconnecting?
2024-04-04T19:44:51.636-07:00 START RequestId: 4c0c58a3-0c33-442c-9dcb-e58ffa71a50a Version: 4
2024-04-04T19:44:52.673-07:00 INFO connectionCheckOutStarted: ConnectionCheckOutStartedEvent { time: 2024-04-05T02:44:52.673Z, address: ‘…’ }
2024-04-04T19:44:52.673-07:00 INFO connectionCheckedOut: ConnectionCheckedOutEvent { time: 2024-04-05T02:44:52.673Z, address: ‘…‘, connectionId: 1 }
2024-04-04T19:44:52.793-07:00 INFO connectionCheckedIn: ConnectionCheckedInEvent { time: 2024-04-05T02:44:52.793Z, address: ‘…’, connectionId: 1 }
2024-04-04T19:44:52.813-07:00 INFO collection.find(() took: 217
2024-04-04T19:44:52.893-07:00 END RequestId: 4c0c58a3-0c33-442c-9dcb-e58ffa71a50a
2024-04-04T19:44:52.893-07:00 REPORT RequestId: 4c0c58a3-0c33-442c-9dcb-e58ffa71a50aDuration: 1257.12 msBilled Duration: 1258 msMemory Size: 128 MBMax Memory Used: 89 MB
Thanks in advance!