주기적으로 발생하는 API 지연 범인 찾기

개요

Fitrun 프로젝트의 데모데이가 다가오면서, 저희 서비스가 안정적으로 운영될 수 있을지 검증이 필요하다고 판단했습니다. 이에 데모데이 참가자 전원이 서비스를 이용한다고 가정하고 부하 테스트를 진행했습니다. 그 과정에서 주기적으로 API 응답 시간이 급격히 튀는 현상을 발견했습니다. 이 글은 이 문제의 원인을 진단하고 해결해나가는 과정을 정리한 글입니다.

 

문제 확인

 

문제를 처음 인지한 것은 로그인 테스트 중이었습니다. 동시 사용자 50명을 대상으로 약 20분간 부하 테스트를 진행하는 동안, 일부 요청의 응답 시간이 2.5초에 근접하거나 이를 초과했습니다. APM과 모니터링 지표를 통해 원인을 분석하려 했지만, 정확히 어느 지점에서 문제가 발생하는지 특정하기는 어려웠습니다.

 

 

 

그리고 동일한 문제가 1시간 부하 테스트에서 더욱 자주 발생했고 10분 내외의 일정한 주기로 발생한다는 점을 확인하게 되었습니다.

 

메모리가 부족한 문제인가??

관련 원인을 찾기 위해 모니터링 지표를 확인했습니다. 그리던 중 응답 시간 지연이 발생하는 주기와 동일한 시간에 메모리 관련 지표에서도 특이점이 보였습니다. 그 중에서도 메모리 PSI 지표에서 눈에 띄게 비슷한 주기로 지연이 발생하는 것을 볼 수 있었습니다.

PSI는 Pressure Stall Infromation의 약자로, 리눅스 커널이 자원 대기 때문에 멈춰 있던 시간에 대한 정보입니다. 위 지표들은 왼쪽에서부터 memory_stalled, memory_waiting 지표입니다.

• memory_stalled: 메모리 부족 때문에 작업이 멈춘 총 시간
• memory_waiting: 프로세스들이 메모리를 기다리느라 대기한 시간

즉, 특정 주기로 메모리 대기가 발생하면서 지연이 발생하고 있었다는 것을 알 수 있습니다.

 

메모리가 많아지면 어떤 동작을 수행하길래

메모리 관련 지표를 보면 API 지연 발생 시점에 메모리 LRU 지표들이 내려가는것을 볼 수 있었습니다.

이게 어떤 의미일까요??

이를 이해하기 위해선 OS가 메모리를 회수하는 동작의 흐름을 이해해야합니다.

메모리가 부족하게 되면 커널은 “메모리 회수” 작업을 수행하게 됩니다. 

The memory management subsystem, also called the virtual memory manager, will subsequently be called “VM”. The role of the VM is to manage the allocation of physical memory (RAM) for the entire kernel and user programs. It is also responsible for providing a virtual memory environment for user processes (managed via POSIX APIs with Linux extensions). Finally, the VM frees up RAM when there is a shortage, either by trimming caches or swapping out “anonymous” memory. (link)

해석하자면 VM(가상 메모리 관리자)은 RAM이 부족한 경우 캐시를 줄이고 익명 메모리를 스왑 아웃하여 메모리 해제한다고 나와있습니다.

 

따라서 위 지표는 LRU(캐시) 메모리가 VM에 의해 메모리 해제가 발생하여 지표가 줄어드는 것을 볼 수 있는 것입니다.

메모리 사용량 지표도 확인해보았습니다.

위 화살표는 응답 지연이 발생한 지점입니다. 지표를 확인해보니 응답 지연이 발생한 시점에 메모리 사용량이 올라간 것을 볼 수 있었습니다. 메모리 사용량이 늘어나 메모리 해제 작업이 일어나고 이것이 응답 지연의 원인이 될 수 있다 생각했습니다.

 

Swap Memory가 문제인가?

그러던 중, VM 인스턴스를 구성할 때 스왑 메모리를 추가로 할당했던 기억이 떠올랐습니다. 현재 인프라는 비용 문제로 GCP의 e2.small을 사용하고 있으며, 이 머신이 제공하는 메모리는 2GB입니다.

VM에는 WAS뿐 아니라 Nginx, Promtail, Node Exporter 등을 모두 Docker로 실행하고 있습니다. 이 모든 프로그램을 동시에 구동하기에는 메모리가 부족할 것이라 판단해, 2GB의 스왑 메모리를 추가로 설정했습니다.

 

스왑 메모리는 물리 메모리(RAM)가 부족할 때 디스크 공간의 일부를 메모리처럼 활용하는 영역입니다. 그러나 디스크에 데이터를 기록하기 때문에 RAM보다 속도가 훨씬 느리고, 디스크 I/O가 빈번해지면 응답 지연이 발생할 수 있습니다.

 

저는 이 스왑 메모리가 문제의 원인일 수 있다고 생각했습니다. 즉, 메모리 사용량이 늘어나면서 스왑 메모리로의 할당 작업이 자주 발생하고, 그로 인해 디스크 I/O가 증가하며 응답 지연이 이어졌을 가능성을 의심했습니다. 이에 스왑 메모리 지표를 확인해보았습니다.

Page Fault, 스왑 메모리 Out, 메모리 사용량 지표에서 지연 발생 시점과 동일한 시점에 수치가 상승하는 것을 볼 수 있었습니다. 하지만 이상하게 맨 처음 지연이 발생하는 시각(18시 10분)에서는 스왑 메모리 지표에서는 특이점이 보이지 않았습니다. 그리고 스왑 메모리 사용량 또한 몇 MiB 수준에 머물렀습니다. 따라서 응답 지연 직접적인 원인보다는 “동반 현상”일 가능성이 크다 생각하고 다른 원인을 찾아보았습니다.

 

로그 기록 문제인가??

서버 요청과 응답을 기록하기 위해 Logback으로 INFO 레벨 로그를 남기고 있었습니다. 서버 앞단의 Nginx 역시 모든 접근과 에러 로그를 파일로 기록하고 있었으며, 이 로그 파일은 Promtail을 통해 모니터링하고 있었습니다.

 

이러한 로그 기록 작업이 부하 테스트 과정에서 상당한 리소스를 소모하고 있는 것은 아닐까 의심하게 되었습니다. 반복된 부하 테스트로 인해 로그 파일 크기는 1GB를 넘어 최대 6GB까지 커졌고, Disk I/O 지표가 급증하는 시점과 응답 지연 시점이 어느 정도 일치하는 모습을 보였습니다.

그래서 로그 기록 레벨을 WARN으로 바꾸고 Nginx도 에러 로그만 기록하도록 수정하고 다시 테스트를 진행해보았습니다. 혹시 모르니 로그를 수집하고 있는 Promtail 컨테이너 자체를 중단했습니다.

 

하지만 여전히 응답속도 지연 문제가 주기적으로 발생했습니다. 이로서 로그 기록이 문제의 직접적인 원인은 아니라는 것을 알 수 있었습니다.

 

특이점이 보이는 지표 정리

다시 문제를 찾기 위해 살펴보았던 지표를 표로 정리해보았습니다.

시각	지연시간	메모리 PSI 상승	LRU 메모리 감소	디스크 I/O 스파이크	디스크 I/O 소요 시간/s	스왑 메모리 상승
12:25				●
12:33	●	●	●	●	●	●
12:43	●	●		●
12:55	●			●	●
13:02	●			●	●
13:13	●	●	●	●	●	●
13:23	●	●	●		●	●
13:49		●

위 표를 보면, 어떤 이유로 디스크 I/O가 증가하면서 메모리 PSI 상승과 LRU 메모리 감소에 영향을 주고, 결국 지연이 발생하는 것으로 보입니다. 그렇다면 진짜 범인은 디스크 I/O를 증가시키는 녀석이겠죠. 로그 기록을 중지한 상태에서도 동일한 지연이 발생했으니, 원인은 로그가 아니라고 판단했습니다. 따라서 다른 요인을 찾기 위해, 누가 디스크 I/O를 발생시키는지 pidstat로 확인한 뒤 다시 부하 테스트를 진행했습니다.

 

그 결과, 지연이 발생하는 정확한 시점에 수상한 프로세스가 실행되는 것을 확인했습니다.

해당 작업을 검색해보니  PCP의 systemd timer가 10분마다 pmlogger 체크/정리 작업을 돌리는 작업이라는 것을 알게 되었습니다.

 

실제로 제 인스턴스에 해당 작업이 등록되어 있는지 확인해보았습니다.

20분 간격으로 진행되는 작업 2개 있었고 각 작업은 10분의 차이가 있었습니다. 즉, 10분 간격으로 두 작업이 번갈아가며 수행되는 것이죠. 이 10분은 응답 지연이 발생하는 주기와 동일했습니다.

 

범인이지 확인해보자.

그러면 이제 진짜 범인인지 확인해봐야겠죠? 해당 스케줄러 작업을 중단한 다음 다시 테스트를 진행해보았습니다. 만약 스케줄러 작업이 범인이라면 10분 주기 지연 작업이 사라져야겠죠.

한 순간 지연이 발생하긴 했지만, Transaction View도 안정적인 패턴으로 보이고 문제였던 10분 주기의 지연 작업은 사라진 것을 확인할 수 있었습니다!

불필요한 스케줄러 제거로 서버 부하도 개선이되어 TPS는 80.4 -> 95.9로 약 19.3% 상승 , MTT는 617.3 -> 517.5 로 약 16.2% 개선할 수 있었습니다.

 

개선 전

개선 후

마무리

이로써 문제를 해결할 수 있었습니다. 원인을 확인해보니, 이전에 메트릭 명령어를 설치하면서 해당 스케줄러가 자동으로 등록된 것으로 보입니다. 메트릭 수집을 계속 유지하려면, 메트릭이 기록되는 디스크와 애플리케이션이 실행되는 디스크를 분리해 부하를 분산하는 방법으로도 해결할 수 있습니다. 하지만 제 경우에는 메트릭 명령어를 더 이상 사용하지 않기 때문에, 스케줄러를 중지하는 방식으로 마무리했습니다.

 

주기적으로 발생하는 지연 문제의 원인을 분석하고 찾는 과정은 생각보다 쉽지 않았습니다. 원인이 될 수 있는 요소가 워낙 많고, 서로 영향을 주고받기 때문에 정확한 진단이 어렵습니다. 그래도 개발 경험이 쌓일수록 원인 파악 속도도 점점 빨라질 것이라 기대합니다. 읽어주셔서 감사합니다.