dev.to

A single console.log was costing us $40,000 a year. I found it by accident.

console.log 한 줄이 연간 4만 달러를 쓰고 있었습니다

요청 본문을 매번 JSON으로 직렬화해 로그 문자열을 만든 뒤, 운영 환경의 로그 수준이 warn이라 버리는 코드가 API 지연과 서버 비용을 키웠습니다. 로거가 출력 여부를 판단하기 전에 문자열을 만들지 않도록 고친 뒤 p99 지연이 낮아지고 인스턴스를 줄여 연간 약 4만 달러를 절감했다고 설명합니다.

에디터 노트

연간 약 4만 달러라는 결과보다 설득력 있는 대목은 비용이 생긴 경로를 구체적으로 짚었다는 점입니다. 로그 수준 검사는 이미 만들어진 문자열을 되돌리지 못하므로, 요청마다 큰 본문을 직렬화하던 코드가 낭비였다는 설명은 원문의 사례와 맞습니다. 다만 절감액은 저자가 제시한 연간 환산치이며, 지연 시간과 인스턴스 변화의 구체적인 수치는 공개하지 않았습니다. 댓글은 로그 수준을 장애 대응 중 올릴 때 요청 본문에 든 토큰이나 인증 헤더까지 기록될 수 있다고 지적합니다. 이는 성능 수정과 별개로 남는 개인정보 보호 문제입니다. 지연 포맷으로 비용을 늦추는 데 그치지 않고 마스킹을 포매터 계층에서 적용하자는 경험담과, 직렬화 호출을 CI에서 잡자는 제안은 이 사례의 빈틈을 보완합니다. 다만 어느 로거에서나 객체 인자 처리가 지연 평가된다고 볼 수는 없으므로 실제 포맷 동작은 사용하는 로거의 구현을 따라야 합니다.

AI 요약

API가 다운되거나 오류를 내지는 않았지만 부하가 커질수록 느려졌습니다. p99 지연이 조금씩 올라가자 팀은 서버를 늘렸고 클라우드 비용도 함께 증가했습니다. 원인은 데이터베이스나 ORM이 아니라 요청마다 실행하던 로그 한 줄이었습니다.

logger.info(Request payload: ${JSON.stringify(req.body)})는 logger.info가 실제로 기록할지 판단하기 전에 템플릿 문자열을 만듭니다. 운영 환경의 로그 수준은 warn이어서 info 로그는 버려졌지만, 그 전에 JSON.stringify가 요청 본문 전체를 직렬화하고 문자열을 새로 할당했습니다. 본문이 수백 KB인 요청도 있었고, 이렇게 쌓인 객체와 문자열은 이후 가비지 컬렉터가 정리해야 했습니다.

비용이 생긴 조건

문제는 요청마다 반복되는 경로에 있었고, 요청 본문 크기에 따라 호출당 비용도 달랐으며, 완성한 로그는 로그 수준 필터에서 매번 버려졌습니다. 각 조건만 따로 보면 놓치기 쉽지만 셋이 겹치면서 불필요한 직렬화와 메모리 할당이 계속 발생했습니다. 작은 입력으로 한 번 실행하는 단위 테스트에서는 비용이 드러나지 않았고, 서비스 전체가 조금씩 느리고 비싸지는 증상만 나타났습니다.

문자열을 미리 만들지 않기

글은 문자열 보간 대신 logger.info('Request payload: %o', req.body)처럼 객체를 인자로 넘기는 방식을 제안합니다. 로거가 로그 수준을 확인한 다음에만 포맷을 처리하는 구조라면 info가 꺼진 운영 환경에서 요청 본문을 직렬화하지 않습니다. 로거가 지연 포맷을 지원하지 않으면 logger.isLevelEnabled('info') 같은 조건으로 먼저 로그 수준을 확인한 뒤 문자열을 만들 수 있습니다.

측정 결과와 적용 범위

저자는 p99 지연이 크게 낮아졌고, 불필요한 할당과 가비지 컬렉션 부담이 줄면서 추가로 띄웠던 인스턴스를 줄였다고 설명합니다. 정확한 지연 시간이나 인스턴스 수는 제시하지 않고, 비용 절감액은 연간 약 4만 달러로 제시합니다. 핵심은 느린 작업을 빠르게 바꾸는 것뿐 아니라, 결과를 버릴 작업을 애초에 수행하지 않는 데 있습니다. 비슷한 낭비가 로그뿐 아니라 메트릭 태그, 오류 메시지, 디버그 코드에도 생길 수 있다고 덧붙입니다.

dev.to 반응

  • @dev_in_the_fog — 템플릿 문자열은 logger.info에 전달되기 전에 호출한 쪽에서 동기적으로 평가됩니다. 로그 수준이 WARN이어도 전체 객체를 직렬화하고 문자열 메모리를 할당해 V8 가비지 컬렉션 부담을 만듭니다. 지연 평가 인자나 로그 수준 검사, 객체를 직접 받는 Pino 같은 구조화 로거를 쓰면 필터링된 로그의 직렬화 비용을 없앨 수 있습니다. 핫 패스의 로그를 점검하라는 좋은 환기입니다.
  • @build996 — 객체를 넘기면 비용은 해결되지만, 장애를 조사하려고 로그 수준을 info로 바꾸는 날에는 전체 요청 본문이 로그 저장소에 기록됩니다. API 요청에는 토큰, 이메일 주소, 사용자가 입력한 내용이 들어갈 수 있습니다. 코드 리뷰에서 한 번 놓쳤으니 사람이 기억하기보다 로거 호출 안의 템플릿 문자열이나 JSON.stringify를 잡는 린트 규칙을 두는 편이 낫습니다.
    • @parsaaftabi — Laravel에서도 장애 때 문제가 생깁니다. PHP는 Monolog가 호출을 받기 전에 문자열 연결과 json_encode를 실행하므로 로그 수준 검사와 상관없이 인코딩 비용을 냅니다. 컨텍스트 배열을 쓰면 핸들러가 레코드를 처리할 때 포맷을 미룰 수 있습니다. 다만 장애 중 로그 수준을 바꾸면 토큰이 로그 저장소에 들어가는 문제는 남습니다. 이런 사례를 본 뒤 로그 호출 안의 json_encode를 grep으로 찾습니다.
    • @yuhehe — 로그 수준을 바꾸면 토큰이 함께 기록될 수 있다는 점이 특히 중요합니다. 저희도 비슷한 일을 겪었습니다. 호출 위치에서 요청 본문을 마스킹했지만 장애 중 당직 엔지니어가 DEBUG를 켜자 요청 흐름의 인증 헤더가 90분 동안 로그 저장소에 들어갔습니다. 지연 포맷은 비용을 핸들러로 미루는 해법이고, 마스킹도 같은 시점에 맡기면 로그 수준과 개인정보 보호가 함께 풀립니다. 그래서 레코드와 로그 저장소 사이의 포매터 한 곳에서 마스킹하도록 옮겼습니다. CI에는 직렬화와 호출 위치 마스킹을 찾는 규칙도 추가했습니다.
  • @yuhehe — 이미 버리기로 한 값을 만들느라 비용을 낸다는 설명이 로그에만 해당하는 문제는 아닙니다. Python에서도 DEBUG가 꺼져 있어도 문자열 연결과 json.dumps가 먼저 실행됩니다. log.debug("payload: %s", body)처럼 인자를 넘기면 로그 수준을 통과한 경우에만 포맷합니다. 핫 패스의 로그마다 문자열 비용을 누가 내는지, 로그가 버려질 때 그 비용도 사라지는지 묻는 점검 질문이 유용합니다. 저희는 크롤러의 코드 리뷰 체크리스트에 디버그 로그 인자 안의 함수 호출을 금지하는 규칙을 넣었고, 프로파일링 중 우연히 문제를 찾았습니다.

원문: dev.to / 번역·요약: Trawling

원문 보기 ↗토론 보기 ↗