프로파일러

프로파일러는 프로그램이 도는 동안 시간이 어디로 가는지 잽니다. 응답이 오래 걸린다는 것은 알겠는데 어느 함수 때문인지 모를 때 붙입니다. 코드를 읽으며 짐작하는 대신 돌려 놓고 세어서 답을 얻습니다.

쉽고 빠른 이해

프로파일러는 프로그램이 도는 동안 함수마다 시간을 얼마나 썼는지 셉니다. 응답이 오래 걸릴 때 어느 함수가 그 시간을 잡아먹고 있는지 이름으로 짚어 줍니다.

코드만 읽어서는 잘 안 보입니다. 시간은 복잡해 보이는 곳이 아니라 자주 불리는 짧은 함수에 쌓입니다. 몇 번 불리는지는 코드가 아니라 들어온 데이터가 정합니다.

도는 모양은 셋입니다.

프로그램을 돌려 놓고 프로파일러를 붙입니다
어느 함수를 도는 중인지 짧은 간격으로 훔쳐보거나, 함수마다 시각을 적게 해 둡니다
모인 기록을 함수별로 합쳐 많이 쓴 순서로 보여 줍니다

대가가 있습니다. 재느라 프로그램이 굼떠지고 그 몫이 결과에 섞입니다. 훔쳐보는 방식은 부담이 적은 대신 드물게 도는 함수를 놓칩니다.

무엇이 오래 걸리는지조차 모르는 단계에서는 이릅니다. 어느 요청이 오래 걸리는지를 먼저 알고 나서 꺼냅니다.

상세

전기 요금이 갑자기 오르면 집 안의 가전을 하나씩 재 보게 됩니다. 냉장고를 의심하다 정작 온수기가 범인이었다는 것을 그제야 알게 됩니다. 프로파일러가 프로그램에 해 주는 일이 이것입니다.

프로파일러는 프로그램을 돌려 놓고 그 안의 어느 함수가 시간이나 메모리를 얼마나 썼는지 모아 보여 주는 도구입니다. 재는 행위가 프로파일링이고, 그 결과로 나온 기록이 프로파일입니다.

짐작이 잘 빗나가는 까닭

고칠 곳을 코드만 보고 고르면 대개 복잡해 보이는 함수를 고릅니다. 그런데 시간은 복잡한 곳이 아니라 자주 불리는 곳에 쌓입니다. 한 번에 몇 줄 안 도는 짧은 함수라도 백만 번 불리면 그 몫이 전체를 덮습니다.

몇 번 불리는지는 코드에 안 적혀 있습니다. 들어온 데이터의 모양과 양이 정합니다. 목록 하나에 항목이 열 개일 때와 만 개일 때, 같은 코드가 전혀 다르게 돌아갑니다.

읽을 코드가 아예 없는 구간도 있습니다. 라이브러리 안쪽과 언어 런타임, 가비지 컬렉션 같은 것은 내가 쓴 코드가 아니지만 시간은 거기서도 씁니다.

엉뚱한 곳을 고치면 헛수고로 끝납니다. 작은 몫을 차지하는 구간을 아무리 줄여도 전체 시간은 거의 안 줄어듭니다. 이 한계를 암달의 법칙이라고 부릅니다. 프로파일러는 고치기 전에 어디를 고쳐야 값이 있는지를 먼저 알려 줍니다.

재는 두 방법 — 훔쳐보기와 심어 두기

시간을 재는 방법은 크게 둘로 갈립니다. 하나는 돌고 있는 프로그램을 짧은 간격으로 훔쳐보는 것입니다. 다른 하나는 함수마다 시각을 적는 코드를 심어 두는 것입니다.

훔쳐보는 쪽이 샘플링 방식입니다. 타이머가 일정 간격으로 프로그램을 잠깐 멈춰 세웁니다. 그때 쌓여 있는 호출 스택을 베껴 둡니다.

호출 스택은 지금 도는 함수와 그 함수를 부른 함수들을 아래로 죽 이어 놓은 목록입니다. 그 한 칸이 스택 프레임 하나입니다.

아래가 그 한 바퀴입니다. 타이머가 깨울 때마다 이 고리를 돕니다.

flowchart TD
    A["타이머가 일정 간격으로 깨운다"] --> B["프로그램을 잠깐 멈춘다"]
    B --> C["쌓여 있는 호출 스택을 베껴 둔다"]
    C --> D["멈춘 것을 다시 돌린다"]
    D --> A
    D --> E["다 모은 뒤 · 함수별로 몇 번 찍혔는지 센다"]

이렇게 한 번 베낀 스택 하나가 표본입니다. 표본의 맨 위가 그 순간 돌고 있던 함수입니다. 그 이름을 모아 세면, 여러 번 찍힌 함수가 그만큼 오래 붙잡고 있었다는 뜻이 됩니다.

아래는 한 요청을 처리하는 동안 찍힌 표본 석 장입니다. 맨 위 칸만 모으면 셈이 끝납니다.

flowchart TD
    subgraph S1["표본 1"]
        A1["맨 위 · 본문 해석"] --- A2["요청 처리"]
    end
    subgraph S2["표본 2"]
        B1["맨 위 · 연결 빌리기"] --- B2["데이터베이스 조회"] --- B3["요청 처리"]
    end
    subgraph S3["표본 3"]
        C1["맨 위 · 본문 해석"] --- C2["요청 처리"]
    end
    S1 --> T["맨 위만 모아 센다 · 본문 해석 2 · 연결 빌리기 1"]
    S2 --> T
    S3 --> T

각 함수가 몇 초 걸렸는지를 직접 재는 것이 아니라, 찍힌 횟수로 시간을 짐작하는 방식입니다.

심어 두는 쪽이 계측 방식입니다. 함수의 들머리와 날머리에 시각을 기록하는 코드를 넣어 둡니다. 드나든 시각의 차이가 걸린 시간입니다. 몇 번 불렸는지도 하나하나 셉니다.

	샘플링 방식	계측 방식
어떻게 재나	일정 간격으로 호출 스택을 베낀다	함수마다 드나든 시각을 적는다
얻는 것	시간이 어디에 몰렸는지의 윤곽	함수별 호출 횟수와 걸린 시간
놓치는 것	드물게 도는 함수는 안 찍힐 수 있다	없다
프로그램이 지는 부담	적다. 운영 중인 서버에도 붙인다	많다. 짧은 함수를 자주 부를수록 늘어난다

결과를 읽는 법 — 자기 시간과 누적 시간

프로파일러의 결과에는 함수마다 두 가지 값이 붙습니다. 누적 시간은 그 함수가 부른 함수들까지 합쳐 그 함수 안에 머문 전체 시간입니다. 자기 시간은 그 함수 자신의 코드가 쓴 시간입니다.

둘을 안 가르면 엉뚱한 곳을 고치게 됩니다. 요청을 받는 맨 바깥 함수는 누적 시간이 거의 전부이지만 자기 시간은 거의 없습니다. 전부를 감싸고 있을 뿐 자기가 일을 하지는 않기 때문입니다.

아래는 찍힌 표본을 함수별로 나눠 본 것입니다. 화살표는 부른 방향입니다. 숫자는 찍힌 횟수입니다.

flowchart TD
    A["요청 처리 · 자기 5회 · 누적 800회"] --> B["본문 해석 · 자기 620회 · 누적 620회"]
    A --> C["데이터베이스 조회 · 자기 20회 · 누적 175회"]
    C --> D["연결 빌리기 · 자기 155회 · 누적 155회"]

손댈 곳은 자기 시간이 큰 함수입니다. 본문 해석이 먼저이고 그다음이 연결 빌리기입니다. 요청 처리는 누적이 가장 크지만 자기 시간이 거의 없으니 고칠 것이 없습니다.

이렇게 호출을 위아래로 이은 것을 가로 막대로 눕혀 쌓아 그린 것이 플레임 그래프입니다. 막대의 너비가 그 함수에 머문 시간입니다. 위로 쌓인 높이는 호출의 깊이입니다. 함수가 수천 개여도 넓은 막대만 눈으로 찾으면 됩니다.

바로 위 그림의 숫자를 그대로 너비로 눕히면 이렇게 됩니다.

block-beta
columns 8
  space:6 d["연결 빌리기 · 155"]:2
  b["본문 해석 · 620"]:6 c["데이터베이스 조회 · 175"]:2
  a["요청 처리 · 800"]:8
  n["칸 너비는 머문 시간 · 위로 쌓일수록 호출이 깊다"]:8

무엇을 시간으로 보느냐에 따라 답이 갈린다

시간을 재는 잣대도 하나가 아닙니다. 프로그램이 CPU(Central Processing Unit, 중앙처리장치)를 붙잡고 계산에 쓴 몫만 세는 잣대가 있고, 시작부터 끝까지 벽에 걸린 시계로 흐른 몫을 세는 잣대가 있습니다. 앞의 것을 CPU 시간, 뒤의 것을 벽시계 시간이라고 부릅니다.

둘이 갈리는 대목은 기다림입니다. 데이터베이스 응답이나 파일 읽기를 기다리는 동안 계산은 안 하므로 CPU 시간은 안 늘지만 벽시계 시간은 흐릅니다. 계산한 몫만 재는 프로파일러를 붙이면, 기다리느라 오래 걸린 요청은 결과에 거의 안 나타납니다.

아래 그림의 첫 줄이 한 요청 안에서 계산과 기다림이 오는 순서입니다. 아래 두 줄은 두 잣대가 각각 세는 칸입니다.

block-beta
columns 6
  a["계산"]:2 b["기다림 · 데이터베이스 응답"]:3 c["계산"]:1
  w["벽시계 시간 · 여섯 칸 전부"]:6
  p1["CPU 시간"]:2 space:3 p2["CPU 시간"]:1

재는 대상이 시간이 아닐 수도 있습니다. 어느 함수가 메모리를 얼마나 할당했는지 세는 것을 메모리 프로파일러라고 부릅니다. 쌓이기만 하고 안 줄어드는 할당을 찾아 메모리 누수가 어디서 시작됐는지 짚는 데 씁니다. 잠금을 기다린 시간을 세는 것도 있습니다.

재는 행위가 결과를 바꾼다

프로파일러는 프로그램 밖에서 구경만 하지 않습니다. 멈춰 세우고, 스택을 베끼고, 시각을 적습니다. 그 일에도 시간이 듭니다. 그래서 잰 결과에는 재느라 든 몫이 섞여 있습니다.

계측 방식이 이 영향을 크게 받습니다. 함수를 드나들 때마다 기록이 붙으므로, 짧은 함수를 아주 많이 부르는 코드일수록 원래보다 크게 나옵니다. 손댈 까닭이 없는 함수가 범인처럼 보이기도 합니다.

컴파일러가 손을 대면 함수 자체가 사라지기도 합니다. 짧은 함수의 내용을 부른 쪽에 펼쳐 넣는 것을 인라이닝이라고 부릅니다. 펼쳐 넣은 코드에는 호출이 없으니 프로파일러의 결과에도 그 이름이 안 나옵니다. 펼쳐 넣기 전후를 나란히 놓으면 이렇습니다.

flowchart TD
    subgraph P1["펼쳐 넣기 전"]
        A1["함수 A"] --> B1["함수 B · 짧다"]
    end
    subgraph P2["펼쳐 넣은 뒤"]
        A2["함수 A · B 의 내용이 안에 들어옴"]
    end
    P1 --> P2
    P2 --> R["결과 목록에 B 라는 이름이 없다"]

그렇다고 최적화를 끄고 재면 운영에서 도는 것과 다른 프로그램을 재게 됩니다. 결과는 잰 조건에서만 참이라고 보는 편이 안전합니다.

부담이 걸린다면 부담을 낮춰 늘 켜 두는 길도 있습니다. 운영 중인 서버에는 부담이 적은 샘플링 방식을 고르고 재는 간격을 성기게 둡니다. 이렇게 늘 조금씩 재 두는 것이 상시 프로파일링입니다.

언제 안 쓰나

시간이 한 프로세스 바깥에서 새고 있으면 프로파일러로는 안 보입니다. 서비스 여러 개를 거치는 요청은 어느 서비스가 시간을 썼는지를 트레이스가 보여 줍니다. 그 안에서 구간 하나하나에 걸린 시간이 적힌 것이 스팬입니다. 프로파일러는 그 구간 하나의 안쪽을 볼 때 씁니다.

아래는 서비스 셋을 거치는 요청 하나입니다.

flowchart TD
    subgraph TR["트레이스 · 요청 하나가 거친 전체"]
        S1["스팬 · 게이트웨이"] --- S2["스팬 · 주문 서비스"] --- S3["스팬 · 결제 서비스"]
    end
    subgraph PR["이 스팬 하나의 안쪽 · 프로파일러가 보는 범위"]
        F1["요청 처리"] --> F2["본문 해석"]
        F1 --> F3["데이터베이스 조회"]
    end
    S2 --> PR

짧게 끝나는 프로그램은 샘플링 방식과 잘 안 맞습니다. 도는 동안 몇 번 못 찍혀서 돌릴 때마다 결과가 달라집니다. 그럴 때는 여러 번 돌려 시간을 재는 벤치마크 쪽이 답을 줍니다.

무엇이 문제인지 아직 모르는 단계에서는 꺼내기 이릅니다. 어느 요청이 오래 걸리는지는 메트릭이 먼저 알려 줍니다. 프로파일러는 범인이 어느 함수인지까지 좁힐 때 꺼냅니다.

프로파일러

상세

짐작이 잘 빗나가는 까닭

재는 두 방법 — 훔쳐보기와 심어 두기

결과를 읽는 법 — 자기 시간과 누적 시간

무엇을 시간으로 보느냐에 따라 답이 갈린다

재는 행위가 결과를 바꾼다

언제 안 쓰나

관련 항목

프로파일러가 읽어 들이는 실행 정보

프로파일러가 시간을 재는 방식

프로파일러가 내놓는 결과를 보는 그림과 지표

프로파일러의 갈래를 가르는 측정 대상

프로파일러를 대신하거나 뒤이어 쓰는 측정 수단

프로파일러로 찾아내는 성능 문제

프로파일러의 측정을 흔드는 실행 조건

프로파일러가 속하는 상위 분류