플레임 그래프

플레임 그래프는 프로그램이 시간을 어디에 쓰는지 한 장의 그림으로 보여 줍니다. 함수 이름을 적은 막대를 부른 함수 위에 불린 함수가 오게 쌓습니다. 오래 머문 함수일수록 막대를 넓게 그립니다. 시간이 몰린 곳은 가장 넓은 막대로 보입니다.

상세

회사의 한 해 비용을 막대로 쌓아 본다고 해 봅시다. 맨 아래에 회사 전체 막대를 깝니다. 그 위에 부서별 막대를, 다시 그 위에 팀별 막대를 쓴 돈만큼 넓게 올립니다. 가장 넓은 막대를 따라 위로 올라가면 돈을 가장 많이 쓴 팀에 닿습니다.

플레임 그래프는 프로파일러가 모은 기록을 이 모양으로 그린 그림입니다. 프로파일러는 프로그램이 도는 동안 어느 함수가 시간을 얼마나 쓰는지 재는 도구입니다. 회사 대신 프로그램이, 부서와 팀 대신 함수가, 돈 대신 시간이 막대에 들어갑니다.

표로는 안 보이는 호출 경로

프로파일러의 결과를 표로 받으면 함수 이름이 수백, 수천 줄 늘어섭니다. 함수마다 쓴 시간이 적혀 있어도 그 함수가 어디서 불렸는지는 표에 안 나옵니다. 같은 함수가 여러 곳에서 불리면 시간이 한 줄로 합쳐져서 어느 경로가 문제인지 가릴 수 없습니다.

호출 관계를 나무 모양으로 펼쳐 주는 호출 트리도 있습니다. 호출 트리는 가지를 하나씩 열어 가며 봐야 합니다. 호출이 깊어지면 몇 번을 열어도 끝이 안 보입니다. 플레임 그래프는 모든 가지를 한 화면에 펼쳐 둡니다. 시간이 몰린 곳은 넓은 막대로 드러납니다. 그 막대 아래를 따라 내려가면 거기에 이른 호출 경로가 보입니다.

재료가 되는 호출 스택

함수가 다른 함수를 부르면, 부른 함수는 불린 함수가 끝나기를 기다립니다. 지금 기다리고 있는 함수들을 부른 순서대로 쌓은 목록이 호출 스택입니다.

호출 스택에서 함수 하나가 차지하는 한 칸을 스택 프레임이라고 부릅니다. 부른 함수가 아래칸에, 불린 함수가 그 위칸에 놓입니다. 뒤에서 「칸」이라고 하면 이 스택 프레임을 가리킵니다.

요청 처리 함수가 본문 해석 함수를 부르고 있다면, 호출 스택은 아래에서 위로 「요청 처리 → 본문 해석」 입니다. 맨 위의 본문 해석이 지금 CPU(Central Processing Unit, 중앙처리장치)에서 도는 함수입니다.

프로파일러는 프로그램이 도는 동안 짧은 간격으로 이 호출 스택을 베껴 둡니다. 이렇게 드문드문 찍어 전체를 짐작하는 방식을 샘플링이라고 합니다.

한 번 베낀 스택 하나를 표본이라고 부릅니다. 어느 함수가 표본에 자주 찍혔다면 그 함수가 그만큼 오래 돌았다는 뜻입니다. 각 함수가 몇 초 걸렸는지는 직접 재지 않습니다. 찍힌 횟수로 시간을 짐작합니다.

같은 스택끼리 묶어 세기

표본은 수천, 수만 개가 쌓입니다. 하나씩 그리면 너무 많으니 먼저 똑같은 스택끼리 묶어 몇 번 나왔는지 셉니다.

아래는 표본 800개를 묶은 결과입니다. 한 줄이 스택 하나입니다. 아래칸부터 위칸까지를 세미콜론으로 이었습니다. 끝의 숫자가 그 스택이 찍힌 횟수입니다.

요청 처리 5
요청 처리;데이터베이스 조회 20
요청 처리;데이터베이스 조회;연결 빌리기 155
요청 처리;본문 해석 620

첫 줄은 요청 처리 함수가 아무것도 안 부르고 자기 코드를 돌던 순간이 다섯 번 찍혔다는 뜻입니다. 둘째 줄도 같은 꼴입니다. 데이터베이스 조회 함수가 연결 빌리기를 부르지 않고 스스로 일하던 순간입니다.

막대로 쌓아 그리기

묶은 결과를 막대로 옮기는 규칙은 둘입니다. 부른 함수 위에 불린 함수를 얹습니다. 막대의 너비는 그 함수가 표본에 찍힌 횟수에 비례합니다.

위의 네 줄을 그리면 아래 그림이 됩니다. 그림의 가로 한 눈금이 표본 50개쯤입니다.

block-beta
columns 16
  d["연결 빌리기 · 155"]:3 space:13
  c["데이터베이스 조회 · 175"]:4 b["본문 해석 · 620"]:12
  a["요청 처리 · 800"]:16

맨 아래 요청 처리 막대가 가장 넓습니다. 모든 표본이 요청 처리에서 시작하기 때문입니다. 한 함수의 막대 너비에는 자기가 일한 시간과, 자기가 부른 함수가 일한 시간이 함께 들어 있습니다. 이 합을 누적 시간이라고 합니다.

막대 위에 아무것도 얹히지 않은 부분은 그 함수가 직접 일한 몫입니다. 이 몫을 자기 시간이라고 합니다. 본문 해석은 위가 전부 비어 있으니 620번 모두가 자기 시간입니다. 요청 처리는 가장 넓습니다. 그런데 위가 거의 다 덮여 있어서 자기 시간은 5번뿐입니다.

이 그림은 눈금 단위로 어림해 그렸습니다. 요청 처리의 자기 시간 5번은 너무 작아서 그림에 안 드러납니다. 데이터베이스 조회 위의 빈 한 눈금이 그 함수의 자기 시간 20번입니다.

세로 높이는 호출이 몇 단계 깊었는지를 나타냅니다. 높이 솟은 탑이라고 시간을 많이 쓴 것은 아닙니다. 시간이 몰린 곳을 가리키는 것은 너비입니다.

막대의 색은 대개 서로 구분되게 하려고 칠할 뿐 값을 담지 않습니다. 붉고 노란 막대가 위로 삐죽삐죽 솟은 모양이 불꽃 같아서 플레임 그래프라는 이름이 붙었습니다.

도구에 따라 뿌리를 위에 두고 아래로 자라게 뒤집어 그리기도 합니다. 이 모양은 고드름을 닮아서 아이시클 그래프라고 부릅니다. 읽는 법은 같습니다.

시간 순서가 아닌 가로축

처음 보는 사람이 가장 자주 잘못 읽는 것이 가로축입니다. 왼쪽에 있는 막대가 먼저 일어났다는 뜻이 아닙니다. 묶은 스택은 대개 함수 이름 순으로 늘어놓습니다. 도구에 따라 넓은 것부터 놓기도 합니다.

이름 순으로 놓는 까닭은 막대를 잇기 위해서입니다. 먼저 표본을 찍힌 차례대로 왼쪽부터 세워 보겠습니다. 아래 그림은 800개 가운데 몇 개만 추려 그린 것입니다.

block-beta
columns 10
  space:2 d1["연결 빌리기"]:1 space:3 d2["연결 빌리기"]:2 space:2
  b1["본문 해석"]:2 c1["데이터베이스 조회"]:2 b2["본문 해석"]:2 c2["데이터베이스 조회"]:2 b3["본문 해석"]:2
  a["요청 처리"]:10

이 그림에서는 데이터베이스 조회가 두 조각으로 갈라져 있습니다. 사이에 본문 해석이 끼어 있어서 하나로 이을 수 없습니다.

이름 순으로 놓으면 앞부분이 같은 스택끼리 나란히 붙습니다. 앞의 800개 예에서 「요청 처리;데이터베이스 조회」와 「요청 처리;데이터베이스 조회;연결 빌리기」가 그런 두 스택입니다. 둘의 아래칸인 데이터베이스 조회가 붙으면서 막대 하나가 됩니다.

앞 절의 그림은 이렇게 모은 결과입니다. 거기서 데이터베이스 조회가 본문 해석보다 왼쪽에 선 것도 이름 순이기 때문입니다.

시간 순서가 궁금하면 가로축이 시간인 플레임 차트를 씁니다. 플레임 차트는 함수가 불린 때에 맞춰 막대를 그립니다. 방금 본 차례대로 세운 그림이 이 꼴입니다. 같은 함수가 열 번 불리면 막대도 열 개가 따로 나옵니다.

넓은 고원 찾기

읽는 첫걸음은 맨 위 가장자리에서 넓고 평평한 막대를 찾는 것입니다. 위에 얹힌 것이 없고 너비가 넓으니 자기 시간이 큰 함수입니다. 이런 막대를 흔히 고원(plateau)이라고 부릅니다.

다음은 그 고원 아래로 내려가며 누가 불렀는지를 봅니다. 해석 함수를 부르는 곳이 요청 처리와 캐시 채우기 두 군데인 경우를 보겠습니다. 그러면 해석 함수 막대도 부른 함수마다 따로 섭니다.

block-beta
columns 8
  x["해석 함수"]:5 space:1 y["해석 함수"]:1 space:1
  r["요청 처리"]:6 k["캐시 채우기"]:2

표에서는 한 줄로 합쳐지던 해석 함수의 시간이 여기서는 경로별로 갈라져 보입니다. 요청 처리 쪽 막대만 넓다면 그 경로만 손보면 됩니다.

넓은 막대가 곧 병목이라고 단정할 수는 없습니다. 그 함수가 일을 많이 하는 것이 당연한 경우도 있습니다. 플레임 그래프는 시간이 어디로 갔는지를 보여 줍니다. 그 시간이 아까운지는 코드를 읽고 판단합니다.

무엇을 세느냐에 따라 달라지는 그림

지금까지 본 그림은 CPU 에서 돌던 순간을 센 것입니다. 표본을 무엇으로 모으느냐만 바꾸면 같은 모양으로 다른 질문에 답할 수 있습니다. 너비가 뜻하는 것이 바뀔 뿐 읽는 법은 같습니다.

둘째 줄이 따로 있는 까닭은 기다리는 함수가 CPU 를 안 쓰기 때문입니다. CPU 에서 돌던 순간만 세면 기다리던 시간은 표본에 아예 안 찍힙니다. 기다린 시간을 센 그림은 오프 CPU 플레임 그래프라고 따로 부릅니다.

두 번 잰 결과를 견줘 볼 수도 있습니다. 늘어난 곳과 줄어든 곳을 다른 색으로 칠한 그림이 차이 플레임 그래프입니다. 배포 전후에 어느 함수가 시간을 더 쓰게 됐는지 찾을 때 씁니다.

이 그림이 답하지 못하는 질문

어디가 문제인지조차 모르는 단계에서 플레임 그래프를 꺼내기에는 아직 이릅니다. 어느 요청이 오래 걸리는지는 메트릭이 먼저 알려 줍니다. 플레임 그래프는 그 요청 안에서 어느 함수가 시간을 쓰는지 좁힐 때 꺼냅니다.

플레임 그래프는 표본을 전부 합쳐 그립니다. 그래서 언제 무슨 일이 있었는지는 사라집니다. 한 시간 동안 모은 표본 가운데 1분만 느렸다면 그 1분은 나머지에 묻혀 거의 안 보입니다. 그럴 때는 시간 순서를 남기는 트레이스나 플레임 차트를 봅니다.

짧게 끝나는 프로그램은 표본이 몇 개 안 찍힙니다. 표본이 적으면 돌릴 때마다 막대 너비가 들쭉날쭉합니다. 이때는 여러 번 돌려 시간을 재는 벤치마크가 더 믿을 만한 답을 줍니다.

컴파일러가 작은 함수를 부르는 쪽 코드에 녹여 넣는 것을 인라이닝이라고 합니다. 인라이닝된 함수는 대개 호출 스택에 따로 남지 않습니다. 그 함수가 쓴 시간은 부른 함수의 자기 시간으로 보입니다.

본문 해석이 숫자 읽기라는 작은 함수를 부르는 경우를 보겠습니다. 인라이닝되기 전에는 숫자 읽기가 본문 해석 위에 제 막대로 섭니다.

block-beta
columns 4
  n["숫자 읽기"]:2 space:2
  b["본문 해석"]:4

숫자 읽기가 인라이닝되면 그 칸이 스택에서 사라집니다. 본문 해석의 위가 통째로 비어 넓은 고원이 됩니다.

block-beta
columns 4
  b2["본문 해석"]:4

넓은 고원이 알고 보니 안에 녹아든 작은 함수의 몫일 수도 있습니다.

관련 항목

플레임 그래프가 그려 내는 실행 정보

호출 스택 · 스택 프레임 · 스택 트레이스 · 샘플링 · 프로파일 · 심볼 테이블 · 디버그 심볼

플레임 그래프의 표본을 모으는 도구

프로파일러 · 샘플링 프로파일러 · perf · async-profiler · py-spy · pprof · eBPF

플레임 그래프에서 읽어 내는 값

자기 시간 · 누적 시간 · CPU 시간 · 벽시계 시간 · 핫스팟

플레임 그래프의 하위 종류

CPU 플레임 그래프 · 오프 CPU 플레임 그래프 · 메모리 플레임 그래프 · 차이 플레임 그래프 · 아이시클 그래프

플레임 그래프와 헷갈리는 이웃 그림

플레임 차트 · 호출 트리 · 호출 그래프 · 트레이스

플레임 그래프로 찾아내는 성능 문제

병목 · 잠금 경합 · 바쁜 대기 · 메모리 누수 · 가비지 컬렉션

플레임 그래프를 흐리게 만드는 실행 조건

인라이닝 · 프레임 포인터 · JIT 컴파일 · 꼬리 호출 최적화 · 스택 되감기

플레임 그래프가 속하는 상위 분류

프로파일링 · 성능 분석 · 성능 · 관측성 · 벤치마크 · 메트릭