Инструменты для разработчика Go: знакомимся с лейблами профайлера

Привет. Меня зовут Марко. Я системный программист в Badoo. Представляю вашему вниманию перевод поста замечательной rakyll о новой фиче в Go 1.9. Мне кажется, что лейблы будут очень полезны для профилирования ваших Go-программ. Мы в Badoo, например, используем аналогичную штуку для того, чтобы тегировать куски кода в наших программах на С. И если срабатывает таймер и в лог выводится стек-трейс, то в дополнение к нему мы выводим такой вот тег. В нем, например, может быть сказано, что мы обрабатывали фотографии пользователя с определенным UID. Это невероятно полезно, и я очень рад, что похожая возможность появилась и в Go.

В Go 1.9 появились лейблы профайлера: возможность добавить пару ключ-значение к семплам, которые делает CPU-профайлер. Профайлер собирает и выводит информацию о самых горячих функциях, где процессор проводит больше всего времени. Вывод обычного CPU-профайлера состоит из имени функции, названия файла исходника и номера строки в этом файле, и так далее. Из этих данных можно также понять, какие части кода вызвали эти горячие функции. Вы даже можете отфильтровать вывод, чтобы получить более глубокое представление о тех или иных ветках исполнения.

Информация о полном стеке вызовов очень полезна, но этого не всегда достаточно для поиска проблемы в производительности. Большое количество Go-программистов используют Go для написания серверов, а понять, где находится проблема производительности в сервере, еще труднее. Сложно отделить одни ветки исполнения от других или сложно понять, когда только одна ветвь исполнения вызывает проблемы (какой-то пользователь или определенный хэндлер). Начиная c Go 1.9 у нас появилась возможность добавлять дополнительную информацию о контексте того, что происходит в данный момент, и использовать в дальнейшем эту информацию в профайлере, чтобы получить более изолированные данные.

Лейблы могут быть полезны во многих случаях. Вот только самые очевидные из них:

• вы не хотите, чтобы абстракции из вашей программы утекали в процесс профилирования, но данные о ваших объектах были бы там полезны. Например, для веб-сервера гораздо полезнее было бы видеть URL в профайлере вместо голых имён функций.
• Стек-трейса недостаточно для того, чтобы понять, кто был инициатором работы. К примеру, обработчик очередей обрабатывает события, которые были созданы кем-то ранее. Обработчик мог бы пометить свою работу именем этого кого-то.
• Для поиска проблемы в производительности критично иметь контекст обработки.

Добавление лейблов

В пакете runtime/pprof появятся несколько новых функций для добавления лейблов. Большинство пользователей будут использовать функцию Do, которая берет контекст, добавляет в него лейблы и передает новый контекст в функцию f:

func Do(ctx context.Context, labels LabelSet, f func(context.Context))

Do записывает набор лейблов только в рамках текущей горутины. Если вы создаете новые горутины в f, вы можете передать контекст в качестве аргумента.

labels := pprof.Labels("worker", "purge")
pprof.Do(ctx, labels, func(ctx context.Context) {
    // Делаем какую-либо работу...

    go update(ctx) // пробрасывает лейблы дальше
})

Работа выше будет помечена лейблом worker:purge.

Смотрим на вывод профайлера

Этот раздел продемонстрирует использование профайлера с лейблами. После того, как вы пометили все интересующие вас куски кода лейблами, время отпрофилировать код и посмотреть на вывод профайлера.

Я буду использовать пакет net/http/pprof в этом примере. Смотрите статью Profiling Go programs, если вам интересны подробности.

package main

import _ "net/http/pprof"

func main() {
    // Много кода...
    log.Fatal(http.ListenAndServe("localhost:5555", nil))
}

Соберем данные по использованию CPU...

$ go tool pprof http://localhost:5555/debug/pprof/profile

После того, как утилита переходит в интерактивный режим, вы можете посмотреть все записанные лейблы командой tags. Заметьте, что pprof-утилита называет их тэги, несмотря на то, что в стандартной библиотеке Go они называются лейблами.

(pprof) tags
http-path: Total 80
        70 (87.50%): /messages
        10 (12.50%): /user

worker: Total 158
       158 (  100%): purge

Как видите, тут два ключа (http-path, worker) и несколько значений для каждого. Ключ http-path указывает на HTTP-хендлеры, а worker:purge указывает на код из примера выше.

Фильтруя по лейблам, мы можем сфокусироваться, например, только на коде из хендлера /user.

(pprof) tagfocus="http-path:/user"
(pprof) top10 -cum
Showing nodes accounting for 0.10s, 3.05% of 3.28s total
      flat  flat%   sum%        cum   cum%
         0     0%     0%      0.10s  3.05%  main.generateID.func1 /Users/jbd/src/hello/main.go
     0.01s   0.3%   0.3%      0.08s  2.44%  runtime.concatstring2 /Users/jbd/go/src/runtime/string.go
     0.06s  1.83%  2.13%      0.07s  2.13%  runtime.concatstrings /Users/jbd/go/src/runtime/string.go
     0.01s   0.3%  2.44%      0.02s  0.61%  runtime.mallocgc /Users/jbd/go/src/runtime/malloc.go
         0     0%  2.44%      0.02s  0.61%  runtime.slicebytetostring /Users/jbd/go/src/runtime/string.go
         0     0%  2.44%      0.02s  0.61%  strconv.FormatInt /Users/jbd/go/src/strconv/itoa.go
         0     0%  2.44%      0.02s  0.61%  strconv.Itoa /Users/jbd/go/src/strconv/itoa.go
         0     0%  2.44%      0.02s  0.61%  strconv.formatBits /Users/jbd/go/src/strconv/itoa.go
     0.01s   0.3%  2.74%      0.01s   0.3%  runtime.memmove /Users/jbd/go/src/runtime/memmove_amd64.s
     0.01s   0.3%  3.05%      0.01s   0.3%  runtime.nextFreeFast /Users/jbd/go/src/runtime/malloc.go

Этот вывод содержит только сэмплы, отмеченные лейблом http-path:/user. И вот в таком выводе мы с легкостью можем понять, где самые нагруженные места /user-хэндлера.

Также вы можете попробовать команды tagshow, taghide и tagignore для дополнительного фильтрования. Например, tagignore дает вам возможность получить данные по всем лейблам, кроме заданного. Фильтр ниже выдаст все, кроме /user хэндлера. В этом случае это worker:purge и http-path:/messages.

(pprof) tagfocus=
(pprof) tagignore="http-path:/user"
(pprof) tags
http-path: Total 70
        70 (  100%): /messages

worker: Total 158
       158 (  100%): purge

Если вы попробуете визуализировать отфильтрованные данные, вывод покажет, сколько каждый лейбл привносит к полной “стоимости”.

Тут видно что worker:purge привнес 0.07s, а хэндлер messages 0.03s в функции generateID.

Попробуйте сами!

Лейблы позволяют вам добавить дополнительную информацию к профайлеру, которая не доступна из простого стека вызовов. Если вам нужны дополнительные размерности в вашем профайлере, то вы можете попробовать это уже сейчас, скачав beta-версию Go 1.9 beta. Также попробуйте пакет pprofutil, чтобы автоматически обернуть ваши HTTP-пути лейблами.

На текущий момент доступна версия Go 1.9 beta 2. Известных багов в ней нет, но команда разработчиков просит попробовать ее на своих программах, а при возникновении проблем сообщить в баг-трекер. Я же хочу сказать, что собрать Go и быть на острие разработки очень и очень просто. Сама же сборка занимает не больше минуты. Дерзайте!