Large DynamoDB latency after creating Provisioned Concurrency

0

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 TimeCaseDynamoDB Latency(ms)Socket Port
102:19:33.276ZRequest when Creating Provisioned Concurrency476.49241304
202:21:02.778ZFirst Request after Creating Provisioned Concurrency202.4833810
302:21:04.357ZSecond Request79.77833810
402:24:07.306ZRequest after a short wait56.86532976

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
Kenryo
preguntada hace 3 meses399 visualizaciones
2 Respuestas
1

To boost latency performance with AWS Lambda provisioned concurrency, consider moving your initialization code outside the main handler and only setting up resources when needed. Be mindful of how this affects billing and try out pre-initialization techniques for smoother invocation handling. Exploring these methods can really speed up your function's response time within provisioned concurrency Lambda setups. Check out the friendly guidelines in the AWS Lambda documentation's section on optimizing latency for more details: link.

Make sure to also take a look at these guidelines for more recommendations on optimizing latency in provisioned concurrency: AWS Lambda Operator Guide - Execution Environments.

profile picture
EXPERTO
respondido hace 3 meses
  • Thank you for your response, Marte!

    I have already done the following

    To boost latency performance with AWS Lambda provisioned concurrency, consider moving your initialization code outside the main handler and only setting up resources when needed.

    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:

    const agent = new Agent({
      keepAlive: true, // Keep connections alive
      keepAliveMsecs: 500, // Lower keep-alive probe delay to more aggressively keep connections open
      maxSockets: 10, // Increase max sockets to allow more concurrent requests per host
      maxTotalSockets: 50, // Set a higher total limit for sockets across all hosts
      maxFreeSockets: 10, // Increase max free sockets to keep more idle connections in a ready state
      keepAliveInitialDelay: 500, // Reduce initial delay for keep-alive probes to keep connections ready sooner
      noDelay: true, // Disable Nagle's algorithm; good for scenarios requiring small, frequent requests
      timeout: 120000, // Adjust timeout to a more reasonable value for your use case
      scheduling: "fifo", // First-in-first-out scheduling for managing request queues
    });

    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.

0

I 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.

Kenryo
respondido hace 3 meses
  • Thinking about this a little, what may be happening in the Lambda environment is that after the connection is made in initialization, the lambda execution environment is paused so no keep-alive pings are sent to keep the connection open and dynamo closes it. In long lived runtimes, where the execution environment isn't paused this issue may not occur.

No has iniciado sesión. Iniciar sesión para publicar una respuesta.

Una buena respuesta responde claramente a la pregunta, proporciona comentarios constructivos y fomenta el crecimiento profesional en la persona que hace la pregunta.

Pautas para responder preguntas