TT Lab
블로그 시작하기
배우기 러닝패스 코스

프로파일링: 느린 요청 하나를 함수까지

플레임 그래프를 읽는 법: 너비, 고원, 내 코드

TT Lab 에서 이어서 보기

한 줄 요약

플레임 그래프의 가로 너비는 시간(표본 수)이고 세로는 호출 깊이이며, 가로 순서에는 뜻이 없습니다. 읽어야 할 것은 위가 비어 있는 넓은 상자(자기 시간이 긴 곳)와, 그 너비를 만든 내 코드의 함수입니다.

왜 이게 필요했나

프로파일 표본은 스택 한 장입니다. 10초에 수천 장이 쌓이면 표로 보기도 어렵습니다. Brendan Gregg 가 2011년 무렵 MySQL 성능 문제를 보다가 만든 그림이 플레임 그래프입니다. 같은 스택을 합치고, 뿌리를 아래에 두고, 함수마다 상자 하나를 그 함수가 나온 표본 수만큼 넓게 그렸습니다. 수천 장의 스택이 한 장의 그림이 되었습니다.

그런데 그림이 쉬워진 만큼 잘못 읽기도 쉬워졌습니다. 가장 넓은 상자는 대개 맨 아래 runtime.goexit 나 main 처럼 모든 일이 지나가는 자리입니다. 가장 높이 솟은 뾰족한 상자는 깊이가 깊을 뿐 시간을 많이 쓴 것이 아닐 수 있습니다.

어떻게 동작하나

그림의 원자료는 접은 스택(folded stacks) 입니다. 한 줄이 스택 하나입니다.

net/http.(*conn).serve;main.quote;main.applyCoupon;main.couponPattern;regexp.compile 512

함수 하나의 두 숫자를 구분합니다.

숫자 뜻 그림에서 pprof 표에서
total(전체) 그 함수가 스택 어딘가에 있던 표본 상자 너비 cum
self(자기) 그 함수가 맨 위(잎)였던 표본 상자 위가 비어 있는 너비 flat

이 코스의 pricing 에서는 main.couponPattern 의 total 이 80% 가까이인데 self 는 거의 0 입니다. 시간은 그 함수가 부른 정규식 컴파일러에서 쓰였습니다. 정규식 파서는 표준 라이브러리라 고칠 대상이 아닙니다. 고칠 대상은 그것을 요청마다 부르게 만든 내 코드입니다. 그래서 읽는 순서는 「넓은 고원을 찾는다 → 그 아래로 내려가 처음 만나는 내 코드를 찾는다」입니다.

runtime.mallocgc 같은 할당기 상자도 같습니다. 여기저기 흩어져 넓게 보이지만, 비용을 만든 쪽은 그 아래의 호출자입니다. 그래서 「mallocgc 가 든 표본 가운데 어느 호출자 아래의 것이 몇 %인가」로 나눠 봐야 합니다.

현장에서 만나는 모습

pprof 의 웹 화면(go tool pprof -http), Pyroscope, Grafana, speedscope 모두 같은 그림을 그립니다. 도구에 따라 뿌리가 위에 있는 icicle 모양이기도 합니다. 「Sandwich」 보기는 함수 하나를 골라 그 위(부른 것)와 아래(부른 쪽)를 함께 보여 주는데, 위에서 말한 「넓은 상자 아래로 내려가기」를 화면이 대신해 주는 것입니다. 어느 도구든 숫자는 같으니, 숫자로 한 번 읽어 두면 화면이 바뀌어도 헤매지 않습니다.

pricing 의 CPU 프로파일을 처음 펼치면 이런 모양이 됩니다. 맨 아래 net/http 의 연결 처리 상자가 거의 전체 너비이고, 그 위로 main.quote, main.applyCoupon, main.couponPattern 이 거의 같은 너비로 쌓이다가 regexp.compile 위에서 수십 갈래로 흩어집니다. 넓은 기둥이 내 코드에서 표준 라이브러리로 넘어가는 그 경계가 고칠 자리입니다. 옆에 붙은 좁은 기둥들(basePrice, reserveStock, buildReceipt)은 일반 주문의 일입니다.

흔히 틀리는 읽기

「가장 높이 솟은 탑이 가장 무겁다」는 틀린 읽기입니다. 높이는 호출 깊이일 뿐이라, 재귀가 깊거나 프레임워크가 겹겹이 감싼 곳이 높게 솟습니다. 무게는 너비입니다.

「자기 시간 1위를 고치면 된다」도 자주 틀립니다. 이 코스의 pricing 에서 자기 시간 1위는 정규식 파서 안쪽이나 메모리 복사 같은 표준 라이브러리 함수입니다. 그 함수를 빠르게 만들 방법은 없고, 부르는 횟수를 줄이는 것이 답입니다. 그래서 잎에서 뿌리 쪽으로 내려가며 처음 만나는 내 코드를 찾습니다.

마지막으로 표본 수를 확인하지 않는 실수입니다. 표본이 몇십 개뿐인 프로파일에서는 3% 와 6% 의 차이가 우연일 수 있습니다. 2CPU 에서 10초를 꽉 채우면 표본은 2,000개 안팎이고, 그 정도가 되어야 몇 % 단위의 차이를 믿을 수 있습니다.

다음 실습에서 할 것

부하를 준 pricing 에서 CPU 프로파일을 받아 접은 스택으로 펴고, self 와 total 을 직접 셉니다. 한 함수만 남겨 좁혀 보고, 할당기의 너비를 호출자별로 나눕니다. 마지막에 읽은 것을 세 문단으로 적습니다.

English corner