AWS Lambda CloudWatch Logs Insights 쿼리로 분석

배포한 lambda function의 cold start와 실제 실행되는 시간을 알아보기 위해 cloudwatch의 로그를 뒤져보았다.

import json

def lambda_handler(event, context):
    print("event: " + json.dumps(event))
    print("Hello, World!")
    return {
        'statusCode': 200,
        'body': json.dumps('Hello from Lambda!')
    }

실행중인 컨테이너가 있는 경우 전부 내려주기 위해 lambda function을 재배포 했다.
이후 여러번 직접 invoke한후 로그를 뜯어보았다.

INIT_START를 통해 python 3.11 런타임 환경에서 인스턴스를 초기화 시키는 것을 확인할 수 있다. cord start로 실행된 것이다.

함수가 종료되어도 REPORT로그를 살펴보면 마지막에 Init Duration이 198.52ms로 초기화하는데 걸린 시간을 확인할 수 있었다.

이후 인스턴스가 내려가기 전에 몇 번 더 invoke 시키고 로그를 확인해 보자.

위 이미지는 같은 함수를 다시 coldstart 부터 인스턴스가 꺼지기 전에 몇번의 호출을 더해서 REPORT 로그들만 필터링해서 인프라 레벨의 로그들만 모아둔 것이다.

확인해보면 위에서와 비슷하게 초기화하는데에는 200.30ms가 걸렸고 이후 함수실행시간은 100ms이하인 것을 확인할 수 있었다.

handler가 간단하고 layer가 없어서인지 생각보다 coldstart에 걸리는 시간이 길지 않은 것 같다. 그래서 FastAPI로 서버를 만들고 mangum을 이용해서 lambda에 배포한 function의 coldstart시간을 확인해보았다.

같은 런타임 환경이고 Package size는 약 50kB이다. duration은 상관이 없어서 서버의 health check하는 router로 요청을 보내서 duration은 아주 짧게 실행되었다.

확인해야할 로그가 몇 개 되지 않는 경우면 이렇게 확인하는 것도 어렵진 않지만 Logs Insights를 이용하면 이런 로그들을 query문을 이용해서 쉽게 분석할 수 있다.

CloudWatch의 Logs에서 마지막 Logs Insights로 들어간다.

그럼 아래와 같이 query를 통해서 log를 분석하고 visualization까지 할 수 있는 화면이 나온다.

화면 우측에 Queries탭을 보면 쿼리를 저장할 수 있는데 Sample queries에 Lambda에 관련한 예시 쿼리들도 있다.

아래 docs에서 자세히 확인할 수 있다.
https://docs.aws.amazon.com/AmazonCloudWatch/latest/logs/CWL_QuerySyntax-examples.html

나는 인터넷에 있는 쿼리를 긁어와서 그대로 사용했다.

filter @type = “REPORT” 

| stats 

 count(@type) as countInvocations , 

 count(@initDuration) as countColdStarts ,     

(count(@initDuration)/count(@type))*100 as percentageColdStarts,

 max(@initDuration) as maxColdStartTime,

 avg(@initDuration) as avgerageColdStartTime,

 avg(@duration) as averageDuration,

 max(@duration) as maxDuration,

 min(@duration) as minDuration,

 avg(@maxMemoryUsed) as averageMemoryUsed,

 max(@memorySize) as memoryAllocated,  (avg(@maxMemoryUsed)/max(@memorySize))*100 as percentageMemoryUsed 

by bin(1h) as timeFrame

위 쿼리를 사용하면 cold start, duration, memory까지 한번에 정보를 쉽게 얻을 수 있다.

invoke 횟수가 13번밖에 안돼서 정확한 정보라고는 못하지만 duration과 cold start시간을 쉽게 확인할수 있다.

이렇게 분석을 하고 싶은데 아직 log가 쌓이지 않았다면 저번에 포스팅한 aws lambda power tuning을 이용해서 test와 동시에 data도 확보할 수 있다.

{
  "lambdaARN": "arn:aws:lambda:ap-northeast-2:860787305217:function:funcion-name",
  "powerValues": [
    128,
    256,
    512,
    1536
  ],
  "num": 20,
  "parallelInvocation": true,
  "payload": {
    "version": "2.0",
    "routeKey": "$default",
    "rawPath": "/health",
    "requestContext": {
      "http": {
        "method": "GET",
        "path": "/health",
        "protocol": "HTTP/1.1",
        "sourceIp": "111.11.111.11",
        "userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/122.0.0.0 Safari/537.36"
      }
    },
    "isBase64Encoded": false
  }
}

위 예시 처럼 excution input에 parallelInvocation": true를 추가해서 병렬로 lmabda function을 invoke시킬 수 있다. 그렇게 되면 대부분의 인스턴스가 병렬적으로 실행되어 cold start되기 때문에 해당 data를 확보할 수 있다.

해당 테스트를 진행해서 각 memory마다 20번의 invoke가 병렬로 일어났고 총 80번의 coungInvokes, countColdStarts를 확인할 수 있다.

lambda에 대한 단점 중 cold start시간이 항상나오는데 내 경우 FastAPI서버와 파이썬 라이브러리를 통째로 올리고, 따로 최적화 작업을 하지 않았는데도 1.5초 정도의 초기화 시간이라면 준수하다고 생각한다.

1.5초의 시간이 치명적인 경우도 있겠지만 해당 함수가 외부 API를 이용해 대부분 AI서비스를 제공하는 서버라 어차피 AI의 답변을 생성하는데 수 초 이상 걸리기때문에 즉각적인 반응이 사용자 경험에 미치는 영향이 미미해서 인지도 모르겠다.

하지만 확실히 해당 방식으로 배포한 서버를 web, app의 backend서버로 사용한다면 크기도 훨씬 커질것이고, cold start가 2, 3초 이상 걸린다면 UX적으로 치명적일 것 같다.

위 방식(서버를 하나의 lambda function으로 배포하는 것)은 하나의 함수만 관리하면서도 여러 endpoint를 운용할 수 있다는 장점이 있지만 그것보다는 즉각적인 반응이 더 중요한 경우가 있다.

그렇다고 provisioned concurrncy(프로비저닝된 동시성)이나 lambda warmer를 바로 이용하는 것은 기술적으로도 생각해야 할 부분이 많고 요금이 추가적으로 발생한다.

하지만 같은 런타임 환경(python 3.11)에서 간단한 handler의 경우 averageColdStartTime이 200ms정도인 것을 보아 lambda function을 여러개로 나누어 배포하고 어느정도의 cold start를 그냥 감수하는 것도 괜찮은 선택인것 같다.