go tool trace

36 minute read

Перевод статьи “go tool trace”

Знаете ли вы как на самом деле работает ваша Go программа? go tool trace может это показать. Этот инструмент при запуске вашей программы визуализирует все события рантайма в довольно удобной форме. Этот инструмент один из самых лучших помощников при поиске проблем с производительностью, параллелизмом и несогласованностью. К сожалению, документации по нему не так много. В своей прошлой статье я упомянул, что мы использовали go tool trace в Pusher для поиска долгих пауз GC. В этой статье я сконцентрирую все внимание на самом инструменте `go tool trace.

Интрефейс go tool trace

go tool trace показывает очень много различной информации, не так просто сходу во всем этом ориентироваться. Для начала нужно разобраться с интерфейсом, а потом потом посмотрим как можно с его помощью решать специфические проблемы.

Пользовательский интерфейс go tool trace, по сути, это веб приложение. Ниже я разместил реальный пример такого приложения. Этот пример визуализирует работу параллельной быстрой сортировки:

Давайте немного поиграемся с этим примером. Для отображения справки, нажмите “?” в правом верхнем углу. Вы можете кликать почти по любому элементу и смотреть дополнительную информацию. Давайте поиграем в небольшую викторину. Попробуйте ответить на вопросы ниже не подглядывая в ответы.

  • Как долго работала эта программа? (Ответ можно найти на временной диаграмме вверху) Ответ: 2.78 milliseconds.
  • Как много go-рутин было запущено на 872 микросекунде работы программы(Для этого можно воспользоваться возможностями зума и изменить масштаб диаграммы, пока не станут различимы отдельные микросекунды, а потом кликнуть на секции “Goroutines” в нужном месте.) Ответ: 3
  • Когда произошло первое увеличение количества тредов операционной системы до 3? (Тут нужно воспользоваться секцией “Threads”) Ответ: 87 микросекунд.
  • Когда из функции main была вызвана функция qSortPar? (Ответ можно найти в секции “PROCS”. Видно, что сначала запускается “G1 runtime.main”. Что происходит после?) Ответ: 510.
  • Что происходит, перед тем как дополнительные процессы(1, 2 и 3) начинают сою работу(Сверху есть есть выпадающий список “View Options” в котором можно выбрать пункт “Flow events”) Ответ: они все были запущены из функции qSortPar в “Proc 0”.
  • Когда процесс 2 был остановлен? (В таймлайне “Proc 2” нужно найти последнее событий) Ответ: на 2.67 секунде

Круто! Как же использовать go tool trace со своей программой?

Вам нужно внести некоторые изменения в вашу программу, чтобы можно было добраться до событий рантайма в вашем бинарнике. Все что вам нужно уже есть в пакете runtime/trace из стандартной библиотеки, необходимо добавить всего пару строк кода. Из видео ниже можно узнать чуть больше подробностей о использовании пакета runtime/trace:

Пример кода, который делает то что нам нужно:

package main

import (
    "os"
    "runtime/trace"
)

func main() {
    f, err := os.Create("trace.out")
    if err != nil {
        panic(err)
    }
    defer f.Close()

    err = trace.Start(f)
    if err != nil {
        panic(err)
    }
    defer trace.Stop()

  // всея остальная логика вашей программы
}

Это позволить сохранят все события, произошедшие в программе, в бинарный файл trace.out. После этого можно запускать go tool trace trace.out. Эта команда распарсит трейт файл и откроет браузер с визуалайзером. По сути, программа запускает встроенный веб-сервер, который отображает распаршенные данные в красивом виде. Как только стартовая страница загрузится, кликните на “View trace”. После этого должна загрузиться страничка, аналогичная примеру выше.

Какие проблемы можно решить с помощью go tool trace?

Давайте поразмышляем над тем как можно решать типичные проблемы с использованием этого инструмента.

Дигностирование проблем с производительностью

Проблемы производительности могут возникать, когда важная go-рутина блокируется до завершения операции. Это может произойти по целому ряду причин: блокировка на системном вызове; блокировка при работе с общей памятью (каналы, мютексы и т.д.); блокировка из-за различных событий рантайма(например, сборка мусора), кроме того, возможно что планировщик не переключает критически важные рутины с необходимой частотой

Все перечисленные выше проблемы могут быть обнаружены с при использовании go tool trace. Вы можете найти признаки таких проблем на тамлайне “PROCS”, достаточно проверить периоды времени когда когда критическая go-рутина необоснованно долго. Как только вы найдете такой период, просто посмотрите что было запущено в этот момент времени. Это, как минимум, подскажет вам в какую сторону копать.

Для примера, посмотрите на проблемы с производительностью, описанные в прошлой статье, обратите внимание на долгие GC паузы:

Красным цветом показан период, когда была запущена только одна go-рутина. При сборке мусора на всех четырех тредах go-рутины запускаются в параллель. Во время фазы сборки мусора “MARK блокируется главная go-рутина. Можете сказать как долго была заблокирована go-рутина runtime.main? На 12 миллисекунд с 626 миллисекунды до 638 миллисекунды.

У меня получилось обнаружить эту проблему вскоре после публикации от команды Go о GC паузах меньше 100 микросекунд. Обнаруженные мною более длинные паузы, которые я увидел с помощью go tool trace, естественно, показались мне странными. Я упомянул об этом в go-nuts рассылке, после чего был заведен баг, который пофиксили в Go 1.8. Правда, мои бенчмарки выявили еще одну проблему с GC паузами, которая остается актуальной на момент написания статьи. Все это было бы невозможно без использования go tool trace

Диагностирование проблем с параллелизмом

Предположим, что вы пишите программу, которая должна максимально утилизировать все CPUs, но она оказывается медленней чем вы ожидали. Это вполне реально, если ваша программа распараллеливается не так как вы ожидали. Например, слишком много критических секций выполняется последовательно, хотя могли бы выполняться асинхронно (и параллельно).

Давайте посмотрим на примере. Скажем, у нас есть шина для pub/sub сообщений, которую мы хотим запустить в одной go-рутине, что позволит безопасно модифицировать мап подписчиков без использования мютексов. Обработчики запроса пишут входящие сообщения в очередь этой шины. Шина читает сообщения из очереди, проходит по мапе с подписчиками, определяет какому подписчику нужно отправить это сообщение, и пишет сообщение в его сокет. Давайте воспользуемся go tool trace чтобы посмотреть, как все выглядит внутри:

Первая зеленая секция показывает где http хендлер читает сообщения из запроса и пишет их в очередь нашей шины. После этого логика обработки сообщений запускается в одном потоке (вторая зеленая секция) и отправляет сообщения подписчикам.

Красные линии отмечают моменты времени, когда сообщения отправляются подписчикам. За какое время буду отправлены все сообщения? Ответ 16 миллисекунд, с 4671 миллисекунды до 4687 миллисекунды.

Проблема в том, что три из четырех тредов простаивают пока выполняется вся логика. Есть ли возможность оптимально их утилизировать? Конечно. Нет необходимости синхронно отправлять сообщения подписчикам. Это можно сделать конкурентно, в разных go-рутинах. Давайте посмотрим как это будет выглядеть:

Как вы можете видеть, теперь логика отправки сообщений работает на всех тредах, в разных go-рутинах.

Но действительно ли это быстрее? Ответ: отправка сообщений в примере выше занимает 16 миллисекунд. А теперь это 10 миллисекунд. Так что, да, это действительно быстрее.

Довольно интересно, что ускорение довольно скромное, несмотря на то что мы использовали в 4 раза больше процессов. Все дело в том, что при параллельной работе приходится мирится с большим оверхедом, связанным с запуском и остановкой go-рутин, работе с общей памятью, разделении кеша. Существует некоторый теоретический предел ускорения, который не позволит нам получить 4х кратное ускорение производительности: Amdahl’s Law.

На самом деле, бывает много ситуаций когда запускать код параллельно менее эффективно. Особенно, если go-рутины работают не долго или очень много общаются друг с другом. Это еще одна причина использования go tool trace, можно попробовать оба варианта и посмотреть что работает лучше.

Когда go tool trace не может вам помочь?

Конечно, go tool trace не может решить все проблемы. Это не самый лучший помощник, если вы хотите найти самые медленно работающие функции или место где программа использует больше всего CPU. Для этого вы можете использовать [go tool pprof](https://blog.golang.org/profiling-go-programs), который покажет вам процент использование CPU в различных функциях вашей программы. go tool trace лучше всего использовать, когда вам нужно понять что именно делает программа, но не для агрегации. Кроме того, есть и другие визуализации на основе go tool trace, наряду с “View Trace”, и они могут быть более удобными для диагностирования блокировок. И, конечно, этот инструмент не заменит теоретические расчеты производительности вашей программы(старое доброе большое 0).

Заключение

Надеюсь, эта статья дала вам базовое представление о использовании go tool trace для диагностики. Даже если у вас нет каких-то специфических проблем, вы можете использовать этот инструмент для проверки своей интуиции, для понимания того как работает рантайм вашего приложения. Я настаиваю на том, чтобы вы пробовали запускать свои программы с использованием этого инструмента. Все примеры в этой статье довольно простые, но проблем симптомы в сложных программах аналогичны рассмотренным здесь.

Дополнение (или “покажите мне код”)

В статье описаны только базовые возможности go tool trace, но вам может захотеть погрузится глубже. Официальная документации по go tool trace довольно скудная. В этом Google документе описано чуть больше деталей. В связи с этим, я рекомендую посмотреть на исходники, чтобы иметь представление как работает go tool trace: