Go 의 다섯 프로파일: CPU 만 보면 놓치는 것
한 줄 요약
Go 의 pprof 는 CPU 말고도 heap(붙잡은 것과 할당한 것), goroutine(지금 멈춘 곳), mutex(잠금을 놓으며 남을 기다리게 한 시간), block(기다린 시간)을 내줍니다. 각각 다른 결함을 가리키고, mutex 와 block 은 켜지 않으면 비어 있습니다.
왜 이게 필요했나
「느려졌다」는 보고의 상당수는 CPU 문제가 아닙니다. 잠금을 기다리는 고루틴은 CPU 를 쓰지 않으니 CPU 프로파일에 나타나지 않습니다. 메모리를 조금씩 붙잡는 누수는 처음 며칠은 아무 증상이 없다가 GC 가 잦아지며 지연을 키우고, 결국 OOM 으로 프로세스를 죽입니다. 응답을 기다리는 채널 앞에서 영원히 멈춘 고루틴도 마찬가지입니다. CPU 프로파일만 보는 습관으로는 이 셋을 놓칩니다.
어떻게 동작하나
import _ "net/http/pprof" 한 줄이면 /debug/pprof/ 아래에 엔드포인트가 생깁니다.
| 주소 | 무엇을 | 언제의 값 |
|---|---|---|
profile?seconds=10 |
CPU 표본(초당 100번) | 받는 10초 동안 |
heap |
inuse(지금 살아 있는 것)·alloc(뜬 뒤 할당한 모든 것) | 지금(마지막 GC 기준) |
goroutine |
고루틴 수와 그 스택 | 지금 이 순간 |
mutex |
잠금 경합으로 남을 기다리게 한 시간 | 켠 뒤 누적 |
block |
채널·잠금에서 막혀 기다린 시간 | 켠 뒤 누적 |
heap 하나에 값이 넷(alloc_objects·alloc_space·inuse_objects·inuse_space) 들어 있다는 점이 중요합니다. 많이 할당하고 곧 버리는 함수는 alloc 에서, 조금씩 영원히 붙잡는 함수는 inuse 에서 1위가 됩니다. 이 코스의 pricing 에서는 alloc 1위가 정규식 컴파일 쪽이고 inuse 1위가 rememberForAudit 입니다. 같은 파일이 두 결함을 가리킵니다.
mutex 와 block 은 기본으로 꺼져 있습니다. runtime.SetMutexProfileFraction(5)(경합 다섯 번에 하나를 기록)과 runtime.SetBlockProfileRate(100000)(100µs 이상 막힌 것을 기록)처럼 켜야 모읍니다. 표본을 모으는 데도 비용이 들기 때문입니다. 그래서 빈 mutex 프로파일은 「경합이 없다」가 아니라 「보고 있지 않다」 입니다. mutex 는 잠금을 놓는 쪽(Unlock)에서 「다른 고루틴을 얼마나 기다리게 했나」를, block 은 기다린 쪽에서 「얼마나 막혔나」를 적습니다.
goroutine 은 스냅숏이라 한 장으로는 누수를 말할 수 없습니다. 일이 끝났는데도 줄지 않고 부하에 비례해 늘어야 누수입니다. 그래서 두 장을 견줍니다.
현장에서 만나는 모습
pprof 엔드포인트를 서비스 포트에 그대로 열어 두는 사고가 반복해서 보고됩니다. 힙 프로파일에는 메모리 내용의 단서가, goroutine 덤프에는 요청 경로와 인자가 들어 있을 수 있습니다. pricing 이 pprof 를 별도 주소의 루프백에만 여는 이유입니다. 운영에서는 내부망 전용 포트나 인증 뒤에 둡니다.
이 코스의 pricing 에는 결함이 넷 들어 있고, 프로파일마다 다른 하나를 가리킵니다. CPU 는 쿠폰 정규식, alloc 은 그 정규식과 영수증 문자열, inuse 는 감사 기록, goroutine 은 받는 쪽 없는 창고 알림, mutex·block 은 재고 잠금입니다.
흔히 틀리는 읽기
heap 프로파일의 inuse 는 「마지막 GC 시점」의 값이라, GC 직후와 직전에 받은 두 장이 다르게 보일 수 있습니다. 누수를 말할 때는 시간을 두고 받은 두 장에서 같은 함수의 inuse 가 계속 늘어나는지를 봅니다. 고루틴과 같은 원리입니다.
goroutine 프로파일의 잎은 거의 늘 runtime.gopark 입니다. 기다리는 고루틴은 모두 거기서 멈추기 때문입니다. 그래서 잎만 보면 아무 정보가 없고, 그 아래에서 처음 만나는 내 코드(이 코스에서는 main.notifyWarehouse.func1)를 찾아야 합니다.
block 프로파일에는 내 코드가 아닌 기다림도 섞입니다. 런타임의 배경 고루틴이 채널에서 오래 기다리는 것이 큰 몫으로 잡히기도 하는데, 그것은 정상적인 대기입니다. 잠금 경합을 볼 때는 내 함수 아래의 Lock 대기만 골라 비율을 봅니다.
다음 실습에서 할 것
부하를 준 뒤 heap 을 받아 inuse 와 alloc 의 1위를 견주고, 큰 주문을 늘려 고루틴 스냅숏 두 장으로 누수를 증명합니다. 켜지 않은 mutex 프로파일이 빈 것을 확인한 뒤 켜고, 쿠폰을 끈 높은 동시성에서 잠금 경합을 잽니다.
English corner
- in-use vs allocated: 「지금 붙잡은 것」과 「지금까지 할당한 것」. 누수는 in-use 에서 보입니다.
- contention: 경합. "lock contention" 은 잠금 하나를 여럿이 다투는 상황입니다.
- goroutine leak: 끝나지 못하고 쌓이는 고루틴. "leaked goroutines blocked on channel send" 같은 문장으로 보고됩니다.
- sampling rate / fraction: 표본 비율. "1 in 5 contention events is reported" 처럼 읽습니다.