Розробка · 5 червня, 11:11 374

Yurii Kolochkov, Software developer and system architect в Yurkol LTD

Дослідження Go програм з pprof

Go надає потужний профайлер, вбудований прямо в рантайм — pprof. Він легкий, безпечний для продакшену і працює з мінімальним оверхедом. Втім, якість і повнота документації залишають бажати кращого. В даній публікації розбираємо pprof з практичної точки зору.

Термінологія.

Що таке профіль?

Профіль — це не лог і не трейс. Go pprof збирає семпли: стек-трейси, які фіксуються періодично (за замовчуванням: кожні 10мс). Кожен семпл представляє «де була програма» в момент зняття семпла. Під капотом використовуються значення IP та SP (instruction pointer та stack pointer) регістрів.

Чим у більшій кількості семплів зустрічається функція, тим більше CPU часу вона ймовірно споживала.

Кожен профіль містить:

Набір семплів
Стек-трейс для кожного семпла
Вагу (наприклад, наносекунди, алокації)
Опціональні теги

Профілі зберігаються як стиснуті protobuf’и (.pb.gz). Вони доступні для аналізу за допомогою go tool pprof, який буде нашим основним CLI інструментом, або такими засобами як GoLand та graphviz etc.

Семплінг.

Семплінг — це компроміс. Він дає статистичну картину без переривання виконання, тому точність результатів не ідеальна, і функція, яка швидко відпрацьовує, може взагалі не з’явитися в профілі.

Це пояснює практичні моменти, напр. — чому flamegraph виглядає порожнім, або чому певні функції не відображаються.

Простоюючий сервер

Почнемо з мінімального HTTP сервера:

package main

import (
    "fmt"
    "net/http"
    "time"

    _ "net/http/pprof"
)

func HelloHandler(w http.ResponseWriter, r *http.Request) {
    resp := fmt.Sprintf("Hello, %s!", r.RemoteAddr)
    _, err := w.Write([]byte(resp))
    if err != nil {
        w.WriteHeader(http.StatusInternalServerError)
        return // !!! Важливо - запобігає множинним записам в http response
    }
}

func main() {
    http.HandleFunc("/", HelloHandler)
    panic(http.ListenAndServe(":8080", nil))
}

Запуск go tool pprof http://localhost:8080/debug/pprof/profile?seconds=10 дає (серед іншого):

Total samples = 0ms

Сервер простоює, немає вхідних запитів — немає CPU активності — немає семплів.

Навіть якщо зробити запит, але обробник нічого не виконує, профіль все одно буде порожнім. pprof записує лише активне виконання.

BurnCPU та реальні дані

Додаємо просту функцію, яка споживає CPU:

package main

import (
    "fmt"
    "math"
    "net/http"
    "time"

    _ "net/http/pprof"
)

func BurnCPU() {
    start := time.Now()
    for time.Since(start) < 300*time.Millisecond {
        for i := 0; i < 1_000_000; i++ {
            r := math.Sqrt(float64(i))
            r = r / 0.3657
        }
    }
}

func HelloHandler(w http.ResponseWriter, r *http.Request) {
    resp := fmt.Sprintf("Hello, %s!\n", r.RemoteAddr)
    BurnCPU()
    _, err := w.Write([]byte(resp))
    if err != nil {
        w.WriteHeader(http.StatusInternalServerError)
        return // !!! Важливо - запобігає множинним записам
    }
}

func main() {
    http.HandleFunc("/", HelloHandler)
    panic(http.ListenAndServe(":8080", nil))
}

Виклик цього в обробнику гарантує реальний семплінг і тепер профіль міститиме корисні діагностичні дані.

Інтерпретація результатів: top

Виконаємо go tool pprof і надішлемо HTTP запит на наш веб-сервер.

Коли профіль зібрано, він буде збережений як файл *.pb.gz у вказаному місці; інтерактивний промпт *pprof* очікує на команди користувача.

Вводим команду top, приклад виводу:

~> go tool pprof http://localhost:8080/debug/pprof/profile?seconds=10
Fetching profile over HTTP from http://localhost:8080/debug/pprof/profile?seconds=10
Saved profile in ****.pb.gz
File: ___go_build_profiling
Build ID: 873234d28c5a94d965d9e0475d203fd4c044e42a
Type: cpu
Time: ************
Duration: 10.10s, Total samples = 3.82s (37.82%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 3810ms, 99.74% of 3820ms total
Dropped 17 nodes (cum <= 19.10ms)
      flat  flat%   sum%        cum   cum%
    3760ms 98.43% 98.43%     3810ms 99.74%  main.BurnCPU
      50ms  1.31% 99.74%       50ms  1.31%  runtime.nanotime (inline)
         0     0% 99.74%     3810ms 99.74%  main.HelloHandler
         0     0% 99.74%     3810ms 99.74%  net/http.(*ServeMux).ServeHTTP
         0     0% 99.74%     3820ms   100%  net/http.(*conn).serve
         0     0% 99.74%     3810ms 99.74%  net/http.HandlerFunc.ServeHTTP
         0     0% 99.74%     3810ms 99.74%  net/http.serverHandler.ServeHTTP
         0     0% 99.74%       50ms  1.31%  time.Since
         0     0% 99.74%       50ms  1.31%  time.runtimeNano
(pprof)

Інтерпретація:

flat: час, проведений безпосередньо у «виконанні» цієї функції
cum (cumulative): час, проведений в цій функції і всьому, що вона викликала
sum%: кумулятивна сума flat% до цього моменту (це інкрементний показник)

Практична порада: якщо sum% досягає 75–90% (читаємо згори донизу), ми вже знайшли основних споживачів. Немає потреби аналізувати глибше.

Тепер дивимося на http-обробник 0 0% 99.74% 3810ms 99.74% main.HelloHandler. Його flat дорівнює нулю, а cum дуже високий, що означає, що дійсну роботу «виконують» функції, що він викликав.

У нашому випадку це (не дивно) BurnCPU 3760ms 98.43% 98.43% 3810ms 99.74% main.BurnCPU, що демонструє високі значення для як для flat, так і cum.

Отже: Якщо функція має flat = 0, але cum > 0, це просто «диспетчер», що передає потік «виконавцю».

top — це не стек викликів

У виводі дані сортовані за споживанням CPU. Це не стек викликів. Те, що дві функції з’являються поруч, не означає, що вони викликали одна одну.

peek та локальний контекст

Виконаємо:

(pprof) peek BurnCPU

Отримаємо дані про ті сутності, які викликають певні функції і навпаки — функції які викликають ці сутності. Це найшвидший спосіб отримати контекст навколо функції, яка є об’єктом аналізу.

(pprof) peek main.BurnCPU
Showing nodes accounting for 3.82s, 100% of 3.82s total
----------------------------------------------------------+-------------
      flat  flat%   sum%        cum   cum%   calls calls% + context
----------------------------------------------------------+-------------
                                             3.81s   100% |   main.HelloHandler
     3.76s 98.43% 98.43%      3.81s 99.74%                | main.BurnCPU
                                             0.05s  1.31% |   time.Since
----------------------------------------------------------+-------------

Але зауважимо: контекст peek не відповідає гарантовано фактичному порядку у стеку, особливо у випадку горутин.

Функції, дані про яких не визначаються

Якщо функція A викликає go B(), а B споживає CPU, побачимо B — але не A.

Тому що A не виконувала роботи, і якщо A також не виконує відносно значущих розрахунків, вона може взагалі не з’явитися в профілі.

Це критично для розуміння flamegraph’ів: запуск чогось не те саме, що виконання.

Візуалізації: svg та web

Для генерації графіків:

(pprof) svg
(pprof) web

Для цього потрібен встановлений graphviz. Отримаємо візуальний граф з блоками (функції), ребрами (виклики) і шириною блоків («вага» CPU).

Якщо програма проста, граф лінійний. Якщо складна/конкурентна, матимемо розгалуження.

Flamegraphs і Callgraphs

callgraph (граф викликів):

Це дерево (граф), де вузли — це функції, а ребра — виклики між ними.

Створюється з усіх зібраних стеків.

Показує, "хто кого викликав" і скільки CPU часу це потребувало.

Розгалуження виникають, коли з однієї функції породжуються інші потоки виконання (типово для конкурентних програм
 або при викликах із різних контекстів).

flamegraph

Це візуалізація callgraph у вигляді «полум’я»:

Висота — глибина стека.

Ширина — кількість семплів (тобто CPU часу).

Гілки відображають вкладеність викликів.

Для інтерактивного веб-інтерфейсу з обома видами запускається локальний сервер, як аргумент — файл профіля для аналізу:

go tool pprof -http=:8080 profile.pb.gz

Це відкриє http://localhost:8080 з вкладками для Graph (callgraph), Flame Graph, Top і Source views. Залишаємо читачеві поекспериментувати з візуальними представленнями даних профілю за допомогою цих команд.

list: представлення на рівні коду

Виконаймо:

(pprof) list BurnCPU

Показує вихідний код по рядках з анотаціями продуктивності. Приклад виводу:

ROUTINE ======================== main.BurnCPU in profiling/main.go
     3.76s      3.81s (flat, cum) 99.74% of Total
         .          .     12:func BurnCPU() {
         .          .     13:   start := time.Now()
         .       50ms     14:   for time.Since(start) < 300*time.Millisecond {
     3.76s      3.76s     15:           for i := 0; i < 1_000_000; i++ {
         .          .     16:                   r := math.Sqrt(float64(i))
         .          .     17:                   r = r / 0.3657
         .          .     18:           }
         .          .     19:   }
         .          .     20:}

Кожен рядок показує flat час (ліва колонка) і cumulative час (права колонка). Рядок 15 показує, де витрачається більшість CPU часу. Зручно для точного визначення областей інтенсивної роботи.

weblist: візуальне представлення на рівні коду

(pprof) weblist BurnCPU

Показує вихідний код по рядках з анотаціями. Якщо семплінг потрапив на рядок, він помічений. Відмінно для локалізації точного гарячого коду — за умови, що вихідні коди доступні.

Включає також дизасемблійований вивід. Може статися в нагоді для низькорівневого аналізу.

Що pprof не може показати

Якщо горутина чекає на мережу або базу даних — будь які зовнішні, I/O операції, pprof не відобразить дані по ній. Очікування — це не споживання CPU.

Ось чому, наприклад, методи, що виконують навіть повільні SQL запити, не з’являються в CPU профілях. Вони не споживають CPU на стороні Go програми.