Hi, Team.
I currently creating a Lambda(Node.js 20.x) to retrieve items from DynamoDB.
I decided to use Provisioned Concurrency because I want to avoid cold starts as much as possible, but I noticed that the latency to DynamoDB after creating Provisioned Concurrency is large.
I want to reduce the latency of DynamoDB after creating Provisioned Concurrency.
Note that I checked SuccessfulRequestLatency, both of which were about 10 ms.
To reduce latency, I tried enabling KeepAlive(※1) on the DynamoDBClient and tried connecting to DynamoDB outside of Lambda's Handler during Provisioned Concurrency creation(※2), but it did not work.
The Lambda log outputs the latency at which DynamoDB retrieved the item and the Socket Port used by the DynamoDB client.
As follows.
No. | Lambda Start Time | Case | DynamoDB Latency(ms) | Socket Port |
---|
1 | 02:19:33.276Z | Request when Creating Provisioned Concurrency | 476.492 | 41304 |
2 | 02:21:02.778Z | First Request after Creating Provisioned Concurrency | 202.48 | 33810 |
3 | 02:21:04.357Z | Second Request | 79.778 | 33810 |
4 | 02:24:07.306Z | Request after a short wait | 56.865 | 32976 |
Latency of No. 2 in the above table is larger than No. 3 and No. 4.
I expect that the small latency of No. 3 is due to the reuse of the connection of No. 2.
Conversely, I expect that the high latency of No. 2 is due to the fact that the No. 1 connection cannot be reused and a new connection is created.
This is because the Socket Port of No.1 and No.2 are different.
And the reason for not reusing the connection is that there was a time gap between No.1 and No.2 requests.
I thought this could be avoided by setting KeepAlive.
I tried the following AWS_NODEJS_CONNECTION_REUSE_ENABLED, but the result did not change. I also tried changing various KeepAlive settings for HttpsAgent but it did not work.
https://docs.aws.amazon.com/sdk-for-javascript/v3/developer-guide/node-reusing-connections.html
The Lambda source and logs are listed below.
I would like to ask for your help.
Thanks.
(※1)See dynamoDBClient.ts
(※2)See lambda.ts
Sources
lambda.ts
import testController from "@/controllers/testController.ts";
console.log("AWS_LAMBDA_INITIALIZATION_TYPE1", {
AWS_LAMBDA_INITIALIZATION_TYPE: process.env.AWS_LAMBDA_INITIALIZATION_TYPE,
});
export const handler = async (event: unknown) => {
console.log("AWS_LAMBDA_INITIALIZATION_TYPE2", {
AWS_LAMBDA_INITIALIZATION_TYPE: process.env.AWS_LAMBDA_INITIALIZATION_TYPE,
});
const response = await testController();
return {
statusCode: response.status,
};
};
if (process.env.AWS_LAMBDA_INITIALIZATION_TYPE === "provisioned-concurrency") {
await testController();
}
testController.ts
import { printSocketInfo } from "@/clients/dynamoDBClient.ts";
import { getTest } from "@/services/testService.ts";
type Response = {
status: number;
};
export default async (): Promise<Response> => {
console.time("getTest");
const test = await getTest();
console.timeEnd("getTest");
printSocketInfo();
return {
status: 200,
};
};
testService.ts
import { GetItemCommandOutput } from "@aws-sdk/client-dynamodb";
import { findTest } from "@/repositories/testRepository.ts";
export const getTest = async (): Promise<GetItemCommandOutput> => {
return await findTest();
};
testRepository.ts
import { GetItemCommand, GetItemCommandOutput } from "@aws-sdk/client-dynamodb";
import dynamoDBClient from "@/clients/dynamoDBClient.ts";
export const findTest = async (): Promise<GetItemCommandOutput> => {
const command = new GetItemCommand({
TableName: process.env.DYNAMODB_TABLE_NAME,
Key: {
part_key: { S: "1" },
sort_key: { S: "2" },
},
});
const result = await dynamoDBClient.send(command).catch(() => {
throw new Error("error");
});
return result;
};
dynamoDBClient.ts
import { DynamoDBClient, DynamoDBClientConfig } from "@aws-sdk/client-dynamodb";
import { NodeHttpHandler } from "@smithy/node-http-handler";
import { Agent } from "https";
const agent = new Agent({
keepAlive: true,
maxSockets: 1,
maxTotalSockets: 1,
maxFreeSockets: 1,
keepAliveMsecs: 1000,
keepAliveInitialDelay: 1000,
noDelay: true,
timeout: 300000,
scheduling: "fifo",
});
const requestHandler = new NodeHttpHandler({
httpsAgent: agent,
requestTimeout: 50,
});
const config: DynamoDBClientConfig = {
region: "ap-northeast-1",
maxAttempts: 5,
requestHandler,
};
export default new DynamoDBClient(config);
export const printSocketInfo = () => {
console.log("requestHandler", requestHandler);
console.log("agent", agent);
for (const [key, socketList] of Object.entries(agent.freeSockets)) {
socketList?.forEach((socket) => {
console.log(`freeSockets:${key} Local port: ${socket.localPort}`);
});
}
for (const [key, socketList] of Object.entries(agent.sockets)) {
socketList?.forEach((socket) => {
console.log(`sockets:${key} Local port: ${socket.localPort}`);
});
}
};
Logs
Request when Creating Provisioned Concurrency
INIT_START Runtime Version: nodejs:20.v16 Runtime Version ARN: arn:aws:lambda:ap-northeast-1::runtime:hoge
2024-02-24T02:19:33.276Z undefined INFO AWS_LAMBDA_INITIALIZATION_TYPE1 { AWS_LAMBDA_INITIALIZATION_TYPE: 'provisioned-concurrency' }
2024-02-24T02:19:33.758Z undefined INFO getTest: 476.492ms
2024-02-24T02:19:33.758Z undefined INFO requestHandler NodeHttpHandler {
metadata: { handlerProtocol: 'http/1.1' },
configProvider: Promise {
{
connectionTimeout: undefined,
requestTimeout: 50,
httpAgent: [Agent],
httpsAgent: [Agent]
}
},
config: {
connectionTimeout: undefined,
requestTimeout: 50,
httpAgent: Agent {
_events: [Object: null prototype],
_eventsCount: 2,
_maxListeners: undefined,
defaultPort: 80,
protocol: 'http:',
options: [Object: null prototype],
requests: [Object: null prototype] {},
sockets: [Object: null prototype] {},
freeSockets: [Object: null prototype] {},
keepAliveMsecs: 1000,
keepAlive: true,
maxSockets: 50,
maxFreeSockets: 256,
scheduling: 'lifo',
maxTotalSockets: Infinity,
totalSocketCount: 0,
[Symbol(shapeMode)]: false,
[Symbol(kCapture)]: false
},
httpsAgent: Agent {
_events: [Object: null prototype],
_eventsCount: 2,
_maxListeners: undefined,
defaultPort: 443,
protocol: 'https:',
options: [Object: null prototype],
requests: [Object: null prototype] {},
sockets: [Object: null prototype] {},
freeSockets: [Object: null prototype],
keepAliveMsecs: 1000,
keepAlive: true,
maxSockets: 1,
maxFreeSockets: 1,
scheduling: 'fifo',
maxTotalSockets: 1,
totalSocketCount: 1,
maxCachedSessions: 100,
_sessionCache: [Object],
[Symbol(shapeMode)]: false,
[Symbol(kCapture)]: false
}
}
}
2024-02-24T02:19:33.776Z undefined INFO agent Agent {
_events: [Object: null prototype] {
free: [Function (anonymous)],
newListener: [Function: maybeEnableKeylog]
},
_eventsCount: 2,
_maxListeners: undefined,
defaultPort: 443,
protocol: 'https:',
options: [Object: null prototype] {
keepAlive: true,
maxSockets: 1,
maxTotalSockets: 1,
maxFreeSockets: 1,
keepAliveMsecs: 1000,
keepAliveInitialDelay: 1000,
noDelay: true,
timeout: 300000,
scheduling: 'fifo',
path: null
},
requests: [Object: null prototype] {},
sockets: [Object: null prototype] {},
freeSockets: [Object: null prototype] {
'dynamodb.ap-northeast-1.amazonaws.com:443:::::::::::::::::::::': [ [TLSSocket] ]
},
keepAliveMsecs: 1000,
keepAlive: true,
maxSockets: 1,
maxFreeSockets: 1,
scheduling: 'fifo',
maxTotalSockets: 1,
totalSocketCount: 1,
maxCachedSessions: 100,
_sessionCache: {
map: {
'dynamodb.ap-northeast-1.amazonaws.com:443:::::::::::::::::::::': <Buffer 30 82 06 cd 02 01 01 02 02 03 03 04 02 c0 2f 04 20 e1 3b 5e 88 e6 bb eb e5 40 a5 4d d7 89 3e be 3c 33 88 d6 6c 55 29 55 73 36 40 24 12 ac a6 84 53 04 ... 1695 more bytes>
},
list: [
'dynamodb.ap-northeast-1.amazonaws.com:443:::::::::::::::::::::'
]
},
[Symbol(shapeMode)]: false,
[Symbol(kCapture)]: false
}
2024-02-24T02:19:33.777Z undefined INFO freeSockets:dynamodb.ap-northeast-1.amazonaws.com:443::::::::::::::::::::: Local port: 41304
First Request after Creating Provisioned Concurrency
...
2024-02-24T02:21:02.981Z 15d68b5c-335d-4331-9e22-9b6b8a44c654 INFO getTest: 202.48ms
...
2024-02-24T02:21:02.982Z 15d68b5c-335d-4331-9e22-9b6b8a44c654 INFO freeSockets:dynamodb.ap-northeast-1.amazonaws.com:443::::::::::::::::::::: Local port: 33810
END RequestId: 15d68b5c-335d-4331-9e22-9b6b8a44c654
REPORT RequestId: 15d68b5c-335d-4331-9e22-9b6b8a44c654 Duration: 281.61 ms Billed Duration: 282 ms Memory Size: 256 MB Max Memory Used: 76 MB Init Duration: 2110.73 ms
Second Request
...
2024-02-24T02:21:04.437Z ca4976c3-a987-4e9d-a469-ecba35d7f514 INFO getTest: 79.778ms
...
2024-02-24T02:21:04.438Z ca4976c3-a987-4e9d-a469-ecba35d7f514 INFO freeSockets:dynamodb.ap-northeast-1.amazonaws.com:443::::::::::::::::::::: Local port: 33810
END RequestId: ca4976c3-a987-4e9d-a469-ecba35d7f514
REPORT RequestId: ca4976c3-a987-4e9d-a469-ecba35d7f514 Duration: 120.00 ms Billed Duration: 120 ms Memory Size: 256 MB Max Memory Used: 76 MB
Request after a short wait
...
2024-02-24T02:24:07.363Z 5b734680-ccc3-4487-bbc9-4711e59f10f7 INFO getTest: 56.865ms
...
2024-02-24T02:24:07.364Z 5b734680-ccc3-4487-bbc9-4711e59f10f7 INFO freeSockets:dynamodb.ap-northeast-1.amazonaws.com:443::::::::::::::::::::: Local port: 32976
END RequestId: 5b734680-ccc3-4487-bbc9-4711e59f10f7
REPORT RequestId: 5b734680-ccc3-4487-bbc9-4711e59f10f7 Duration: 71.20 ms Billed Duration: 72 ms Memory Size: 256 MB Max Memory Used: 76 MB
P.S.
Provisioned Concurrency Setting up
2024-03-02T11:39:59.385Z INIT_START Runtime Version: nodejs:20.v16 Runtime Version ARN: arn:aws:lambda:ap-northeast-1::runtime:660a9e193c3308bf378f98e9cccc1c6e75c9c39c457df58189605033509e1044
2024-03-02T11:40:01.091Z 2024-03-02T11:40:01.091Z undefined INFO AWS_LAMBDA_INITIALIZATION_TYPE1 { AWS_LAMBDA_INITIALIZATION_TYPE: 'provisioned-concurrency' }
2024-03-02T11:40:01.552Z 2024-03-02T11:40:01.552Z undefined INFO getTest: 422.338ms
2024-03-02T11:40:01.570Z 2024-03-02T11:40:01.570Z undefined INFO freeSockets:dynamodb.ap-northeast-1.amazonaws.com:443::::::::::::::::::::: Local port: 39200
About 1 minute and 15 seconds later(Port Changed)
2024-03-02T11:41:16.921Z START RequestId: cef52ae0-0dab-412c-bf7c-3f518ee871fb Version: 41
2024-03-02T11:41:17.063Z 2024-03-02T11:41:17.063Z cef52ae0-0dab-412c-bf7c-3f518ee871fb INFO getTest: 133.648ms
2024-03-02T11:41:17.065Z 2024-03-02T11:41:17.065Z cef52ae0-0dab-412c-bf7c-3f518ee871fb INFO freeSockets:dynamodb.ap-northeast-1.amazonaws.com:443::::::::::::::::::::: Local port: 48712
About 1 minute later(Port Not Changed)
2024-03-02T11:42:04.414Z START RequestId: dd6a7d73-a67e-405c-90c9-ce3d9a4e0186 Version: 41
2024-03-02T11:42:04.421Z 2024-03-02T11:42:04.421Z dd6a7d73-a67e-405c-90c9-ce3d9a4e0186 INFO getTest: 5.666ms
2024-03-02T11:42:04.429Z 2024-03-02T11:42:04.429Z dd6a7d73-a67e-405c-90c9-ce3d9a4e0186 INFO freeSockets:dynamodb.ap-northeast-1.amazonaws.com:443::::::::::::::::::::: Local port: 48712
About 1 minute later(Port Not Changed)
2024-03-02T11:43:01.066Z START RequestId: 36a6da5a-565f-44c6-b02b-9efd7b973afb Version: 41
2024-03-02T11:43:01.072Z 2024-03-02T11:43:01.072Z 36a6da5a-565f-44c6-b02b-9efd7b973afb INFO getTest: 5.488ms
2024-03-02T11:43:01.072Z 2024-03-02T11:43:01.072Z 36a6da5a-565f-44c6-b02b-9efd7b973afb INFO freeSockets:dynamodb.ap-northeast-1.amazonaws.com:443::::::::::::::::::::: Local port: 48712
About 1 minute later(Port Not Changed)
2024-03-02T11:44:00.322Z START RequestId: 0de83729-0e3d-44b5-88b9-46bf430fd0c1 Version: 41
2024-03-02T11:44:00.330Z 2024-03-02T11:44:00.330Z 0de83729-0e3d-44b5-88b9-46bf430fd0c1 INFO getTest: 7.402ms
2024-03-02T11:44:00.331Z 2024-03-02T11:44:00.331Z 0de83729-0e3d-44b5-88b9-46bf430fd0c1 INFO freeSockets:dynamodb.ap-northeast-1.amazonaws.com:443::::::::::::::::::::: Local port: 48712
About 1 minute later(Port Not Changed)
2024-03-02T11:45:00.315Z START RequestId: 31440e38-0233-49b4-841d-668cc4790c5b Version: 41
2024-03-02T11:45:00.320Z 2024-03-02T11:45:00.320Z 31440e38-0233-49b4-841d-668cc4790c5b INFO getTest: 4.604ms
2024-03-02T11:45:00.321Z 2024-03-02T11:45:00.321Z 31440e38-0233-49b4-841d-668cc4790c5b INFO freeSockets:dynamodb.ap-northeast-1.amazonaws.com:443::::::::::::::::::::: Local port: 48712
About 1 minute and 5 seconds later(Port Changed)
2024-03-02T11:46:06.046Z START RequestId: a404fe5b-83a4-4a35-be8a-fa016c9a59f8 Version: 41
2024-03-02T11:46:06.077Z 2024-03-02T11:46:06.077Z a404fe5b-83a4-4a35-be8a-fa016c9a59f8 INFO getTest: 29.814ms
2024-03-02T11:46:06.077Z 2024-03-02T11:46:06.077Z a404fe5b-83a4-4a35-be8a-fa016c9a59f8 INFO freeSockets:dynamodb.ap-northeast-1.amazonaws.com:443::::::::::::::::::::: Local port: 51014
About 1 minute later(Port Not Changed)
2024-03-02T11:47:05.529Z START RequestId: 5659941d-a0fe-4a5a-920d-c9e41dc67fc4 Version: 41
2024-03-02T11:47:05.535Z 2024-03-02T11:47:05.535Z 5659941d-a0fe-4a5a-920d-c9e41dc67fc4 INFO getTest: 4.449ms
2024-03-02T11:47:05.535Z 2024-03-02T11:47:05.535Z 5659941d-a0fe-4a5a-920d-c9e41dc67fc4 INFO freeSockets:dynamodb.ap-northeast-1.amazonaws.com:443::::::::::::::::::::: Local port: 51014
About 1 minute and 5 seconds later(Port Changed)
2024-03-02T11:48:11.169Z START RequestId: 9daf1b15-b5fd-4594-83d1-b9aa459a6455 Version: 41
2024-03-02T11:48:11.217Z 2024-03-02T11:48:11.217Z 9daf1b15-b5fd-4594-83d1-b9aa459a6455 INFO getTest: 47.166ms
2024-03-02T11:48:11.218Z 2024-03-02T11:48:11.218Z 9daf1b15-b5fd-4594-83d1-b9aa459a6455 INFO freeSockets:dynamodb.ap-northeast-1.amazonaws.com:443::::::::::::::::::::: Local port: 50612
About 1 minute and 5 seconds later(Port Changed)
2024-03-02T11:49:16.995Z START RequestId: fd5c6131-ba9e-489f-a8cf-7fed9832792c Version: 41
2024-03-02T11:49:17.062Z 2024-03-02T11:49:17.062Z fd5c6131-ba9e-489f-a8cf-7fed9832792c INFO getTest: 65.877ms
2024-03-02T11:49:17.063Z 2024-03-02T11:49:17.063Z fd5c6131-ba9e-489f-a8cf-7fed9832792c INFO freeSockets:dynamodb.ap-northeast-1.amazonaws.com:443::::::::::::::::::::: Local port: 60666
Thank you for your response, Marte!
I have already done the following
Please see lambda.ts. I am calling the testController method outside of the Lambda handler. In testController, I am calling dynamoDBClient.ts. Subsequent processing uses the DynamoDBClient generated at this time.
Just to be sure, I tried moving the processing in the dynamoDBClient.ts to lambda.ts and modifying the code to use the DynamoDBClient generated there, but it did not work.
Is the connection between the instance of Provisioned Concurrency and DynamoDB not maintained for a long time using KeepAlive? I checked the logs and it seems that the latency increases roughly after a minute and a half.
Try this agent configuration:
Resources:
Thank you, Marte! Sorry for the late reply.
I have tried the Agent settings you suggested. As it turns out, it did not work.
I then checked with AWS support and they replied that the connection is disconnected from the DynamoDB side.
It seems that the DynamoDB connection is disconnected after roughly 1 minute and 5 seconds.
Please check the logs of the connection to DynamoDB when it was executed after about 1 minute and 1 minute and 5 seconds, as I added the logs.
The port number of the connection after about 1 minute is the same as the connection before that. On the other hand, the port number of the connection made about 1 minute and 5 seconds later is different from the previous one. TCP KeepAlive seems to have no effect.
Preparation time for Provisioned Concurrency takes more than 1 minute 30 seconds. This means that requests made after Provisioned Concurrency is created will always have to regenerate the connection.
Unfortunately, I am going to give up on this issue and try to find another solution. I would be happy if the preparation time for Provisioned Concurrency could be shortened in the future.
Thank you for your help.