SLASH 23 리뷰 - 프로파일러로 시스템 성능 향상시키기: Pinpoint, 힙 덤프, jemalloc, async-profiler, strace, 그리고 커널 버전
서버 플랫폼 팀 리더가 팀에서 쓰는 프로파일러 여섯 가지(Pinpoint, 힙 덤프+MAT, jemalloc, async-profiler, strace/perf trace, Binary Ninja)를 실제 사례 하나씩과 함께 소개하는 발표다. 각 사례가 짧지만 “어떤 증상에 어떤 도구를 꺼내는가”의 매핑이 명확하고, 마지막에 Istio 프록시의 3중 커넥션 비용을 Unix 도메인 소켓으로 줄여본 실험과 커널 버전 업그레이드의 중요성이 나온다. 2년 전 같은 발표자의 서버 기술 스택이 지도였다면 이 발표는 공구함이다. 내용은 발표 영상과 자동 생성 자막을 근거로 했고, 표현은 내 말로 바꿨다.
도구와 사례
서비스를 운영하다 보면 갑작스러운 리소스 사용 증가나 응답 속도 저하를 만난다. 대부분 코드 변경 사항을 확인해 해결하지만 그렇지 않은 경우도 있고, 그때 프로파일러가 서비스 내부에서 무슨 일이 일어나는지 알려준다.
| 도구 | 용도 | 사례 |
|---|---|---|
| Pinpoint | MSA 분산 트랜잭션 분석, 요청 스택에서 어느 코드가 얼마나 걸렸는지 | Spring Cloud Config 서버 응답 지연 |
| 힙 덤프 + MAT | JVM 힙 분석 | Old 영역 급증과 GC 시간 증가 |
| jemalloc | 네이티브 메모리 분석 | 컨테이너 메모리가 할당량을 넘는 문제 |
| async-profiler | CPU·메모리·wall-clock 샘플링, perf 이벤트 병행 | Elasticsearch CPU, Spring Cloud Gateway 메모리 |
| strace / perf trace | 시스템 콜 분석 | Redis 응답 지연이 애플리케이션 문제인지 시스템 문제인지 |
| Binary Ninja | 리버스 엔지니어링 | 외부 라이브러리 오류 원인 파악 |
Pinpoint: 설정 서버가 느리다. 여러 서비스가 공통으로 쓰는 설정은 Spring Cloud Config 서버에 있고 배포 시 가져온다. 배포 완료 시간이 예상보다 길어 프로세스를 분석하니 Config 서버 응답이 느렸다. Pinpoint에 Config 서버 코드를 분석하는 옵션을 주고 보니 하나의 메서드가 계속 실행 중이었다. 코드를 보니 암호화된 필드를 하나하나 복호화하고 있었다. 하나에 5ms면 1,000개에 5초, 2,000개에 10초다. 단일 스레드 복호화를 멀티 스레드로 바꿔 원하는 수준으로 개선했다.
힙 덤프: Old 영역이 빠르게 늘고 GC 시간이 길다. 결국 GC되긴 하지만 GC 시간을 줄이려고 힙 덤프를 떴다. 덤프를 뜰 때 기본적으로 GC가 발생해 분석 대상이 사라지므로 -all 옵션을 주면 GC 대상도 남고 MAT에서 해당 옵션을 선택해 보존할 수 있다. 가장 많은 영역을 차지하는 객체를 찾거나 MAT의 OQL로 의심 객체를 찾고, 어느 클래스에서 쓰였는지 트리로 확인한 뒤 코드를 본다. 첫 사례는 Redis 응답 속도 메트릭을 쌓으면서 새 객체를 계속 만든 것으로, 옵션을 껐다. 둘째는 JSON 라이브러리가 필드 이름을 캐싱하면서 늘어난 경우로, 필드명이 고정이면 문제없지만 계속 새 필드명이 생기면 메모리가 높아진다. 해당 옵션을 끄고 쓴다.
jemalloc: 컨테이너 메모리 초과. 컨테이너 메모리는 사용량보다 여유를 줘서 할당하지만 예상치 못하게 더 쓰려는 경우가 있다. 힙은 최대치가 정해져 있어 문제가 안 되고 대부분 네이티브 메모리다. LD_PRELOAD에 jemalloc을 설정해 동작시키고 프로파일 결과를 PDF로 변환하면 메모리 트리가 보인다. LD_DEBUG로 심볼 매칭을 보면 malloc은 libc에서 jemalloc으로 바뀌었지만 mmap은 여전히 libc라 mmap으로 할당하는 경우는 jemalloc으로 발견할 수 없다. PDF를 하나하나 보다가 zip 관련 항목을 찾았고, 코드를 보니 close가 호출되지 않고 있었다. close를 추가하고 다시 돌리니 zip 항목이 사라졌고 투입 이후 메모리가 늘지 않았다. (같은 계열의 토스페이먼츠 네이티브 메모리 누수 발표도 같은 도구로 다른 원인을 찾았다.)
async-profiler: Elasticsearch의 날짜 파싱. CPU와 메모리를 프로파일링하고 일정 시간마다 샘플을 수집하는 wall-clock 모드가 있어 스레드가 멈춰 있는 경우도 확인된다. 애플리케이션 스택과 리눅스 perf 이벤트를 함께 샘플링해 시스템 분석도 동시에 된다. 결과는 플레임 그래프나 JFR로 저장하고 JFR은 IntelliJ에서 편하게 본다. 토스는 로그 검색에 Elasticsearch를 쓰는데 로그량이 많아 CPU 부하가 심해지고 있었다. 내부 코드를 정확히 모르는 경우도 돌려보면 어디서 CPU를 쓰는지 안다. 날짜 관련 필드가 하나뿐인데 과하게 쓰이는 것처럼 보여 코드를 찾아보니, 쓰던 포맷이 ISO 형식의 긴 날짜 문자열이었다. 사람이 읽기는 편하지만 날짜로 변환하는 데 epoch millis 숫자보다 오래 걸린다. 간단히 비교하니 epoch millis 성능이 뛰어났다. 프로파일 없이 옵션만 봤다면 지나쳤을 것이다.
async-profiler: Gateway의 반복 파싱. Spring Cloud Gateway를 정기적으로 프로파일링하다 메모리가 많이 쓰이는 부분을 찾았다. 요청이 들어오면 라우트 개수만큼 주소를 파싱하는데, 같은 주소가 다시 와도 또 라우트 개수만큼 파싱했다. 라우트를 미리 파싱해 캐시하는 것으로 대응했고 주소에서 라우트를 바로 찾아 성능이 대폭 향상됐다.
strace: Redis가 느린 게 누구 탓인가. 애플리케이션 로그에서 Redis 응답이 느렸고 Pinpoint도 같았다. 네트워크 문제 같아 tcpdump로 보니 Redis가 늦게 보내는 경우도 있었고 Redis는 빨리 보냈는데 애플리케이션이 늦게 받는 경우도 있었다. 후자에 집중했다. 패킷을 받은 뒤 애플리케이션이 처리하는 과정에는 시스템 콜과 이벤트 루프가 있으니 둘 중 하나가 늦은 것이다. 이벤트 루프는 네트워크 데이터를 기다리므로 “패킷이 왔는데 기다리는 것”과 “안 와서 기다리는 것”이 구분되지 않는다. 그래서 시스템 콜을 봤다. perf trace를 쓰고 싶었지만 커널 버전이 낮아 strace로 확인했다(프로파일 중 성능이 떨어지는 단점이 있고 perf trace가 훨씬 낫지만 낮은 커널에서는 지원되지 않는다. 빌드된 perf가 없으면 커널 tools에서 빌드해 쓸 수 있다). 응답이 느린 스레드를 찾아 비슷한 시간대의 strace 로그를 보니 read 시스템 콜 뒤에 <unfinished>, 다음 줄에 <resumed>가 있고 240ms가 걸렸다. 왜 240ms 뒤에 올라왔는지 추가 분석하려 했지만 CentOS에서 Rocky로 OS를 바꾸며 커널 버전을 올리는 중이라 그 뒤에 다시 보기로 했고, Rocky로 바꾼 뒤 200ms 이상 걸리는 현상은 사라졌다.
커널 버전이 중요한가. 의문이 있었는데 perf 자료를 조사하며 중요하다고 생각하게 됐다. perf c2c는 CPU 캐시의 false sharing을 분석하는데, false sharing이 발생하면 CPU 성능에 큰 영향을 주고 Netflix 사례처럼 사용률 차이가 크다. 이를 리눅스 커널이 지속적으로 개선하고 있고(false sharing으로 검색되는 커밋들), 여러 사례를 종합하면 커널 업그레이드가 성능에 도움이 된다.
Binary Ninja: 라이브러리 오류가 라이선스 문제였다. 외부 라이브러리에 문제가 났는데 히스토리가 없거나 담당 회사 대응이 느리면 스스로 원인을 파악하고 싶다. 우리가 로그와 정보를 많이 줄수록 상대도 빠르게 대응한다. 좋은 디컴파일러는 어셈블리보다 훨씬 보기 쉽게 보여준다. 레거시 코드를 컨테이너화하던 중 라이브러리가 문제였는데, Binary Ninja로 에러 지점의 작업을 확인해 라이선스 문제임을 바로 파악했고, 담당 회사에 문의해 라이선스 파일을 바로 받아 해결했다.
Istio의 3중 커넥션과 Unix 도메인 소켓 실험
Istio는 이점이 많지만 단점도 있다. 클라이언트 ↔ 클라이언트 사이드 프록시, 클라이언트 프록시 ↔ 서버 프록시, 서버 프록시 ↔ 애플리케이션까지 커넥션이 셋 존재한다. 갑작스러운 트래픽 증가로 새 커넥션이 필요할 때 프록시가 없을 때보다 3배 많은 연결을 맺어야 한다. 프록시 간 통신은 HTTP/2를 적용해 비용을 낮췄다. 클라이언트-프록시, 프록시-서버 구간은 Merbridge나 Cilium 같은 eBPF로 소켓을 바로 연결해 중간 과정을 없애거나 Istio Ambient Mesh처럼 터널을 쓸 수 있다. 하지만 eBPF는 커널 버전에 따라 지원 범위가 달라서, 낮은 커널에서 eBPF를 쓰기보다 두 프로세스 간 통신인 Unix 도메인 소켓을 적용해 봤다. 클라이언트와 프록시가 바로 연결되어 커넥션 비용이 없으니 Merbridge와 같은 효과를 기대했고, 적용하면 Envoy가 .sock 파일로 리스닝한다. 갑작스러운 요청 증가에 더 좋은 응답성을 보이지만 애플리케이션이 Unix 도메인 소켓을 쓰도록 수정이 필요했고, 지금까지는 컨테이너에서 직접 접근하면 mTLS가 풀린 상태로 tcpdump가 가능했는데 UDS를 쓰면 파이프라인으로 패킷을 확인해야 하는 불편이 생겼다. 그래서 시스템 전체에 쉽게 적용되고 패킷 분석의 불편이 없는 방식을 더 고민 중이다.
다음: 자동화
같은 장애를 다시 겪지 않기 위해 자동화하려 한다. Pinpoint로 서비스 스택을 분석해 문제 패턴이 있는지 파악하고 배포 과정에 적용하면 장애 예방이 가능할 것 같다. JFR 분석을 자동화해 CPU·메모리가 많이 쓰이거나 기존 대비 비약적으로 증가하는 부분을 담당자에게 알린다. eBPF로 애플리케이션·네트워크·시스템 지표를 분리해 장애 시 빠른 원인 분석에 쓴다. 이 계획은 1년 뒤 eBPF 관측 발표로 이어진다.
리뷰
“어떤 증상에 어떤 도구”의 표가 이 발표의 가치이고, 각 사례가 그 표의 근거다. 느린 API는 Pinpoint, 힙은 MAT, 힙 밖은 jemalloc, CPU는 async-profiler, 애플리케이션인지 시스템인지 모르면 strace. 도구 소개 발표는 흔하지만 “Elasticsearch 날짜 포맷을 epoch millis로 바꿨다”, “Gateway가 같은 주소를 라우트 수만큼 반복 파싱했다” 같은 구체적 발견이 붙어 있어 각 도구를 언제 꺼내야 하는지가 기억에 남는다.
“정기적으로 프로파일링한다”는 한 문장이 중요하다. Gateway 사례는 장애가 나서 본 것이 아니라 정기 프로파일링에서 나왔다. 프로파일러를 장애 대응 도구가 아니라 예방 도구로 쓰고, 그것을 자동화하겠다는 마무리가 자연스럽다.
Redis 240ms 사례는 결론이 “커널을 올리니 사라졌다”로 끝난다. 원인을 끝까지 파지 못한 것을 발표자가 그대로 말했고, 그 대신 false sharing과 커널 개선 커밋을 근거로 “커널 버전이 중요하다”는 교훈을 뽑았다. 원인 규명의 미완을 감추지 않으면서 일반화 가능한 결론을 낸 정직한 마무리다. 2년 뒤 Spring 구동 시간 줄이기에서도 같은 도구들이 등장한다.
남는 질문
- Config 서버의 복호화를 멀티 스레드로 바꿨다면 암호화 필드 수천 개가 정상인지. 설정 자체를 줄이거나 복호화 결과를 캐시하는 방향은 검토했는지.
- jemalloc으로 못 잡는 mmap 할당은 어떻게 추적하는지. NMT나
pmap차분으로 보는지. - Unix 도메인 소켓 실험은 프로덕션에 적용했는지, 아니면 tcpdump 불편 때문에 보류했는지. 이후 Ambient Mesh를 검토했는지.
- Rocky 전환 후 사라진 240ms 지연의 원인을 나중에 찾았는지. 커널의 어떤 변경이 영향을 준 것인지.
댓글
아직 댓글이 없습니다