잡다한 IT 지식

AWS fcm 병목 지점 찾기 본문

AWS/트러블슈팅

AWS fcm 병목 지점 찾기

가나무마 2025. 7. 10. 01:00

문제 상황


저희 팀 프로젝트는 사기 의심 거래가 발생하면 FCM을 통해 사용자에게 알림을 보내도록 설계했습니다.
이제 첫 테스트를 하는 중인데 첫 번째 알림 발송까지 무려 33초가 걸렸습니다.
아래는 CloudWatch Log insights를 통해 추출한 로그입니다.

[
    {
        "@timestamp": "2025-07-09 08:50:41.765",
        "@log": "secret:/aws/lambda/FinGuard-Backend-dev-createTransaction"
    },
    {
        "@timestamp": "2025-07-09 08:51:14.996",
        "@log": "secret:/aws/lambda/sns-receive-and-send-fcm"
    }
]

거래 발생 → FCM 발송 사이까지 걸린 시간이 무려 33초입니다.
트래픽이 없던 상황임에도 이 정도의 지연은 비정상적입니다.

문제 원인 추측


추측1. Cold Start

서버리스 아키텍처이므로 Lambda의 Cold Start로 인한 지연 문제일 가능성이 있습니다.
Init Duration에 얼마나 많은 시간이 소요 되는 지 확인해보겠습니다.
 
CloudWatch Log Insights

CloudWatch Log Insights에서 로그를 쿼리할 수 있다.

 
아래는 Init Duration의 평균, 최대, 최소 시간 쿼리문입니다.

fields @timestamp, @message
| filter @message like /Init Duration/
| parse @message /Init Duration: (?<init_duration>[0-9.]+) ms/
| stats     
    count() as cold_starts,    
    avg(init_duration) as avg_init_ms,    
    max(init_duration) as max_init_ms,    
    min(init_duration) as min_init_ms

 

Init Duration 로그 집계 결과

결과는 다음과 같습니다.

  • 평균 시간: 782ms
  • 최대 시간: 1550ms
  • 최소 시간: 68ms

즉, Cold Start는 아무리 길어도 2초를 넘지 않습니다.
최악의 경우를 가정해도 총합해서 걸리는 시간은 1550ms * 3(Lambda 개수) = 4.65초 수준입니다.

추측2. Lambda 타임아웃으로 인한 SQS 메시지 재처리

로그를 확인해보면, SQS 메시지를 처리하던 Lambda가 실패한 뒤 약 24초 후(Lambda 타임아웃 시간 포함 30초)에 다시 실행되는 현상을 확인할 수 있습니다.

실행에 실패한 Lambda가 다시 시작된다.

이 30초라는 시간은 바로 SQS의 기본 Visibility Timeout(가시성 제한 시간) 때문입니다.

SQS 메시지 가시성 제한 시간은 기본 30초다.

 
문제의 원인은, Lambda가 SageMaker serverless endpoint를 호출했지만 endpoint의 Cold Start로 인해 Lambda가 응답을 받지 못하고  타임아웃 되기 때문입니다.
이로 인해 SQS의 메시지는 삭제되지 않은 채 invisible 상태로 유지되었고, Visibility Timeout이 만료된 시점에 다시 visible 상태로 전환되면서 같은 메시지로 Lambda가 재실행된 것입니다.
 

SQS에 거래 내역 메시지가 도착한다.

 
 

SQS는 Lambda를 트리거하며 해당 메시지는 가시성 제한 처리 된다.

 
 

Lambda가 SageMaker에 요청을 보낸다.

 
 

SageMaker Serverless Endpoint는 Cold Start로 인해 프로비저닝에 많은 시간을 소요한다.

 

6초가 지나도 SageMaker는 여전히 프로비저닝 중이며 Lambda는 시간 제한 초과로 종료된다.
Lambda 실행 시간 6초 + 24초 => 30초가 지나 SQS 메시지 가시성 제한이 해제된다.

 

SQS가 다시 Lambda를 트리거하고 SageMaker에 요청한다. SageMaker는 이전 요청으로 인해 프로비저닝이 끝난 상태이므로 Lambda에게 바로 응답한다.

 
 

해결 방안


  1. Lambda 함수 제한 시간 상향

Lambda 함수가 SageMaker의 응답을 안정적으로 받을 수 있도록 기존 6초였던 Lambda의 시간 제한을 20초로 여유 있게 설정했습니다.

재발 방지


  1. Lambda 타임아웃 발생 시 CloudWatch Alarm 설정

 

에러 발생 시 Slack으로 알림을 보내서 개발자가 대처를 할 수 있도록 CloudWatch Alarm을 설정했습니다.