Автор: А тем временем я продолжаю разбираться в том, как дебагить .NET Core приложения в Linux. Теперь я уже более или менее представляю, как анализировать проблемы с памятью, но таких на самом деле у нас не так уж и много. Самая распространённая проблема — загрузка процессора под 100%, и тогда очень, очень хочется понять, чем же это приложение таким занимается.
На Windows я первым делом лезу в логи и трейс-файлы. Когда их не хватает, приходит очередь PerfView, который с огромной частотой сэмплирует приложение, и тогда уже можно посмотреть, сколько потоков сейчас запущено, чем они занимаются, какие самые горячие места, и т. п.
Логи и трейсы, разумеется, существуют и на Linux, но мне было интересно, можно ли на нём профайлить .NET Core примерно так же, как и на Windows. Как оказалось, инструментов почти куча, но применительно к .NET Core основными выглядят три: утилиты perf, lttng и perfcollect. Вот на них мы сейчас и посмотрим.
Песочница (профайлинг идёт следом)
Нам нужно тестовое .NET Core приложение для профайлинга, линуксовый хост и какие-нибудь инструменты разработчика на нём. Так как Vagrant и VirtualBox ещё никто не отменял, всё это можно сделать за минуты.
Во-первых, тестовое приложение, которое тупо делает много бессмысленной математики в бесконечном цикле:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 |
using System; using System.Linq; namespace calc { class Program { static int UpperLimit => (Int32)(DateTime.UtcNow.Subtract(new DateTime(1970, 1, 1))).TotalMinutes; static int Sum() => Enumerable.Range(0, UpperLimit) .Aggregate((result, current) => unchecked(result + current)); static int Mul() => Enumerable.Range(0, UpperLimit) .Aggregate((result, current) => unchecked(result * current)); static void DoSomeMath() { Sum(); Mul(); } static void Main(string[] args) { while (true) { DoSomeMath(); } } } } |
Во-вторых, вот нам Vagrantfile, который и хост с Убунтой создаст, и .NET Core SDK с perf, lttng и perfcollect установит:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 |
Vagrant.configure("2") do |config| config.vm.box = "ubuntu/xenial64" config.vm.network "forwarded_port", guest: 80, host: 8080 config.vm.provider "virtualbox" do |vb| vb.memory = "4096" end config.vm.provision "shell", inline: <<-SHELL # python 2.7 apt-get update apt-get install -y python2.7 vim # dotnet curl https://packages.microsoft.com/keys/microsoft.asc | gpg --dearmor > microsoft.gpg mv microsoft.gpg /etc/apt/trusted.gpg.d/microsoft.gpg sh -c 'echo "deb [arch=amd64] https://packages.microsoft.com/repos/microsoft-ubuntu-xenial-prod xenial main" > /etc/apt/sources.list.d/dotnetdev.list' apt-get update apt-get install -y dotnet-sdk-2.1.3 # perf apt-get install -y linux-tools-`uname -r` # lttng apt-add-repository -y ppa:lttng/stable-2.10 apt-get update apt-get install -y lttng-tools lttng-modules-dkms liblttng-ust-dev # perfcollect # curl -OL http://aka.ms/perfcollect SHELL end |
Теперь, выполняем vagrant up и начинаем развлекаться.
Ищем «горячие» функции с perf
Это просто удивительно, как легко начать делать что-то с perf. То есть документации, примеров и зубодробительных концепций под капотом хватает, но, чтобы получить мало-мальский полезный результат, нужно совсем немного.
Так как Vagrantfile нам всё установил, вот, что мы сейчас сделаем: сбилдим и запустим тестовое приложение в фоновом режиме, а потом посмотрим, чем же оно занимается изнутри.
|
1 2 3 4 5 6 7 8 9 |
dotnet build #Microsoft (R) Build Engine version 15.5.179.9764 for .NET Core #... #Build succeeded. # 0 Warning(s) # 0 Error(s) dotnet bin/Debug/netcoreapp2.0/calc.dll & #[1] 13689 |
Запуск приложения в фоновом режиме возвращает очень полезное число — 13689. Полезное потому, что это айдишка процесса приложения, и она нам понадобится, чтобы натравить на него perf. Кроме PID мы ему дадим параметр -g, чтобы в отчётах были стеки вызовов, и команду record, чтобы начать сэмплирование.
Итак, запускаем perf, даём ему возможность пособирать статистику секунд десять или около того, и останавливаем веселье при помощи ctrl+C:
|
1 2 3 4 |
sudo perf record -p 13689 -g #^C[ perf record: Woken up 4 times to write data ] #failed to mmap file #[ perf record: Captured and wrote 0.899 MB perf.data ] |
Барабанная дробь — смотрим отчёт:
|
1 |
sudo perf report |
Ну, что я скажу. Красиво, конечно, но не то, чтобы как-то особенно полезно. В таблице с отчётом выведены все функции, которые хоть раз выполнялись, пока perf собирал статистику. Для каждой из них: в первом столбце — как долго выполнялись дочерние функции, а во втором — как долго выполнялась она сама.
Если бы я искал проблемы в производительности, то высматривал бы функции, у которых «дочернее» и «собственное» время заметны и примерно равны — то есть функция работала много и выполняла самы себя. Я вижу аж четыре кандидата внизу списка, но вот незадача — адреса функций есть, а имён — нет.
Но к счастью для нас в CoreCLR есть секретный выключатель, который поможет perf собрать и имена тоже. Это переменная окружения COMPlus_PerfMapEnabled, которой нужно задать единицу и передать либо напрямую процессу, либо установить всей сессии (export COMPlus..):
|
1 2 3 4 5 6 7 |
COMPlus_PerfMapEnabled=1 dotnet bin/Debug/netcoreapp2.0/calc.dll & #[1] 13723 sudo perf record -p 13723 -g #^C[ perf record: Woken up 14 times to write data ] #failed to mmap file #[ perf record: Captured and wrote 3.378 MB perf.data ] |
Да, есть ещё такой момент. Так как perf запускался через sudo , а dotnet и CoreCLR — нет, то у отчёта perf и маппинг файлов CLR скорее всего будут разные владельцы, что для perf очень и очень печально. С другой стороны, если ему сказать -f, то на владельцев файлов ему внезапно станет накласть:
|
1 |
sudo perf report -f |
Красота? Практически все имена на месте, и сразу видно, что самые «горячие» функции — Aggregate и две лямбды для сложения и умножения, которые мы ей передавали.
Смотрим результат в FlameGraph
Отчёт-таблица — это, конечно, здорово, но если бы было можно посмотреть результат в виде графика, как в том же Google Chrome, то было бы вообще прекрасно. И это, оказывается, очень просто сделать. Нужно скачать проект FlameGraph и скормить ему результаты perf через два perl файла: stackcollapse-perf и flamegraph:
|
1 2 3 4 |
# Get FlameGraph git clone --depth=1 https://github.com/BrendanGregg/FlameGraph # Convert perf data to flamegraph.svg sudo perf script | FlameGraph/stackcollapse-perf.pl | FlameGraph/flamegraph.pl > flamegraph.svg |
Так как моя Убунта запущена без UI, то посмотреть результирующий SVG файл с графиком было бы проблематично. С другой стороны, на машине есть установленный python2.7 и проброшенный к хостовой машине восьмидесятый порт (80->8080, Vagrantfile), так что можно запустить временный веб-сервер и посмотреть картинку через браузер на хостовой машине:
|
1 |
sudo python -m SimpleHTTPServer 80 |
Ничего нового картинка, конечно, не сказала, но зато как красиво! Кстати, там всё кликабельно и мыше-двигательно, так что можно и увеличить отдельные ветки, и посмотреть детали в тултипе.
Собираем события рантайма через lttng
Есть типы дотнэтовских событий, которые было бы проблематично слушать через perf. Всякие там сборки мусора, загрузки assemblies, брошенные и отловленные ошибки. Возможно, какие-то их следы и можно было бы заметить в perf отчётах, но скорее всего те редкие события были бы похоронены под более частыми вызовами пользовательских функций.
С другой стороны, дотнэтовский рантайм умеет генерировать целый набор сообщений/событий как раз о таких вещах, и если их включить, то при помощи уже другой утилиты lttng можно будет всё это собрать. События включаются через ещё одну переменную окружения COMPlus_EnableEventLog, и ей тоже нужно значение 1.
Чтобы сделать жизнь немного интереснее, добавим-ка мы в тестовый проект кусок кода, который выбрасывает и тут же отлавливает ошибку. Снаружи ничего не будет видно, но заглушенные ошибки в продакшене, в общем-то, хороший повод спросить, а всё ли нормально там.
Итак, изменения в коде:
|
1 2 3 4 5 6 7 8 9 10 11 |
//... DoSomeMath(); try { throw new Exception("Completely useless exception"); } catch { // Good luck finding it } //... |
Билдим/запускаем:
|
1 2 3 4 |
dotnet build # ... COMPlus_EnableEventLog=1 dotnet bin/Debug/netcoreapp2.0/calc.dll & # [1] 13824 |
И теперь будем слушать события. Пользоваться lttng чуть-чуть сложнее, чем perf, потому что нужно и сессию создать, и на события подписаться, и запустить всё это дело. А потом и выключить в обратном порядке. Но на самом деле всё вменяемо.
Единственная загадка: какие вообще события дотнэт рантайм поддерживает, чтобы знать, на что подписываться? Чтобы не пришлось лезть в исходники дотнэта и собирать события по-одному, можно скачать perfcollect скрипт, в котором все они перечислены в одном месте. Это всего-лишь малая часть того, что там есть:
|
1 2 3 4 5 6 7 8 |
DotNETRuntime:ExceptionThrown_V1 DotNETRuntime:ExceptionCatchStart DotNETRuntime:ExceptionCatchStop DotNETRuntime:ExceptionFinallyStart DotNETRuntime:ExceptionFinallyStop DotNETRuntime:ExceptionFilterStart DotNETRuntime:ExceptionFilterStop DotNETRuntime:ExceptionThrownStop |
Нам, в принципе, только и ошибки и нужны, так что можно подписаться сразу на все через маску:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 |
lttng create mysession #Session mysession created. #Traces will be written in /home/ubuntu/lttng-traces/mysession-20171226-060602 lttng enable-event --userspace --tracepoint DotNETRuntime:Exception* # UST event DotNETRuntime:Exception* created in channel channel0 lttng start # Tracing started for session mysession # Few seconds later lttng stop # Waiting for data availability # Tracing stopped for session mysession lttng destroy # Session mysession destroyed |
lttng результаты идут в очень бинарных файлах, так что смотреть их лучше при помощи babeltrace утилиты, которая, насколько я понимаю, установилась одновременно с lttng. Имя файла с результатами мы уже знаем (строка после lttng create), так что смотрим:
|
1 2 3 4 5 |
babeltrace ~/lttng-traces/mysession-20171226-060602/ # ... # [06:06:36.109917648] (+0.503586579) ubuntu-xenial DotNETRuntime:ExceptionThrown_V1: { cpu_id = 0 }, { ExceptionType = "System.Exception", ExceptionMessage = "Completely useless exception", ExceptionEIP = 139875671834775, ExceptionHRESULT = 2148734208, ExceptionFlags = 16, ClrInstanceID = 0 } # [06:06:36.109950251] (+0.000032603) ubuntu-xenial DotNETRuntime:ExceptionCatchStart: { cpu_id = 0 }, { EntryEIP = 139873639728404, MethodID = 139873626968120, MethodName = "void [calc] calc.Program::Main(string[])", ClrInstanceID = 0 } # ... |
Конечно, отчёт не показывает, где именно ошибка произошла, да и стека события нет, но мы ясно видим текст ошибки, её тип, где она была поймана, и этого более чем достаточно для диагностики.
Собираем всё подряд через perfcollect
В одном из дотнэтовских репозиториев есть утилитка под названием perfcollect, которая собирает практически всё то же самое, что и perf с lttng. Более того, perfcollect на самом деле всего-лишь обычный bash скрипт, который эти самые perf с lttng и вызывает. Казалось бы, зачем он тогда упал? Есть, оказывается, причины:
- У него есть команда
install, которая устанавливает практически все зависимости, включаяperfиlttng, и эта команда понимает, как работать на разных дистрибутивах Linux. - Как и PerfView на Windows, все собранные данные упаковываются в один zip архив, которым удобно меняться с товарищами и рабочими машинами.
- Если показать ему, где лежит дотнетовская
crossgenутилита, то perfcollect сможет собрать немного больше дебаггинг информации, чемperfиlttngпо-отдельности. - У
perfcollectесть командаview, которая может показать отчёт как вperf, так и вlttng. Знать одну команду всегда проще, чем две. - Отчёт
perfcollectможно перенести на виндовую машину и смотреть уже в PerfView.
И на самом деле им очень просто пользоваться. Скачиваем один файл, делаем его исполняемым, просим установить зависимости, и начинаем работать.
|
1 2 3 4 |
curl -OL http://aka.ms/perfcollect chmod +x perfcollect sudo ./perfcollect install #... |
Так как perfcollect будет пользоваться и perf, и lttng, то нужно устанавливать уже обе переменные окружения:
|
1 2 |
COMPlus_PerfMapEnabled=1 COMPlus_EnableEventLog=1 dotnet bin/Debug/netcoreapp2.0/calc.dll & # [1] 13622 |
Профайлим:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 |
sudo ./perfcollect collect mysession -pid 13622 #Collection started. Press CTRL+C to stop. #^C #...STOPPED. # #Starting post-processing. This may take some time. # #Generating native image symbol files #...SKIPPED #Crossgen not found. Framework symbols will be unavailable. #See https://github.com/dotnet/coreclr/blob/master/Documentation/project-docs/linux-performance-tracing.md#resolving-framework-symbols for details. #Saving native symbols #...FINISHED #Exporting perf.data file #...FINISHED #Compressing trace files #...FINISHED #Cleaning up artifacts #...FINISHED # #Trace saved to mysession.trace.zip |
Результат собрался в mysession.trace.zip, и его можно посмотреть всё там же, в perfview:
|
1 |
./perfcollect view mysession.trace.zip |
|
1 2 3 4 5 |
./perfcollect view mysession.trace.zip -viewer lttng # ... # [03:54:15.882946185] (+?.?????????) ubuntu-xenial DotNETRuntime:ExceptionThrown_V1: { cpu_id = 1 }, { vpid = 13622, vtid = 13622, procname = "dotnet" }, { ExceptionType = "System.Exception", ExceptionMessage = "Completely useless exception", ExceptionEIP = 140623183495319, ExceptionHRESULT = 2148734208, ExceptionFlags = 16, ClrInstanceID = 0 } # [03:54:15.883036311] (+0.000090126) ubuntu-xenial DotNETRuntime:ExceptionCatchStart: { cpu_id = 1 }, { vpid = 13622, vtid = 13622, procname = "dotnet" }, { EntryEIP = 140621151601940, MethodID = 140621138841656, MethodName = "void [calc] calc.Program::Main(string[])", ClrInstanceID = 0 } # ... |
Всё знакомо, всё понятно.
Добавляем crossgen
Если подсунуть perfcollect утилитку crossgen, то, теоретически, собранный им отчёт, будет немного полнее — он сможет подтянуть детали о нативных дотнэтовских библиотеках. К сожалению, о том, как именно подсунуть ему crossgen и где вообще того достать, нужно немного подумать.
Во-первых, простейший способ найти правильный crossgen — это опубликовать наше приложение с dotnet publish. В этом случае NuGet подтянет всевозможные дотнетовские зависимости и среди всего прочего положит crossgen себе в кэш ~/.nuget:
|
1 2 3 |
dotnet publish -r ubuntu-x64 find ~/.nuget -name crossgen #/home/ubuntu/.nuget/packages/runtime.linux-x64.microsoft.netcore.app/2.0.0/tools/crossgen |
Во-вторых, perfcollect будет искать crossgen в той же папке, где лежит и libcoreclr.so, используемый нашим приложением. Но вот, чтобы узнать, где же этот libcoreclr лежит, нужно немного постараться.
- Для опубликованных приложений
libcoreclr.soбудет лежать вpublish, рядом с собранным приложением. - Для приложений вроде нашего, которые отдалживают рантайм у хостовой машины,
libcoreclr.soбудет лежать в папке с остальным рантаймом, и нам надо просто знать, какая его версия используется нашим приложением, и где вообще он, собственно, находится. Так как на моей убунте есть только .NET Core SDK 2.1.3, и я знаю, что он идёт в комплекте с рантаймом версии 2.0.4, то всего-то нужно найти libcoreclr, в пути к которому есть эти цифры.
И такой действительно есть:
|
1 2 3 |
sudo find / -name libcoreclr.so # ... # /usr/share/dotnet/shared/Microsoft.NETCore.App/2.0.4/libcoreclr.so |
Я бы точно не делал ничего подобного в продакшене, но во временной виртуальной Убунте не грех скопировать crossgen прямиком в рантайм:
|
1 2 3 |
sudo cp \ /home/ubuntu/.nuget/packages/runtime.linux-x64.microsoft.netcore.app/2.0.0/tools/crossgen \ /usr/share/dotnet/shared/Microsoft.NETCore.App/2.0.4/ |
Если мы запустим perfcollect ещё раз, то он уже не будет жаловаться на отсутствующий crossgen. С другой стороны, я не заметил никакой разницы в результатах на Убунте. Возможно, появилось бы что-нибудь новое на Винде в PerfView, но и того, что я собрал без crossgen, мне хватило.
Вместо заключения
Самая большая проблема во всём этом выяснении, как профайлить .NET Core приложения на Linux, — какие именно задавать вопросы Гуглу. Всё-таки пропасть между моим обычным околовиндовым вэбовским опытом и юниксовой экосистемой для профайлинга очень ощутима, а чтобы искать что-то неизвестное, нужно сначала знать, что именно мне неизвестно.
Но мне повезло наткнуться на цикл постов (вроде такого) от Саши Голдштейна, которые дают отличную начальную площадку, от которой можно уже копать дальше. Более того, он уже писал и о perf, и lttng c perfcollect, так что теперь я думаю: писать об инструментах, которые уже описали другие, — это плагиат, или ещё нет? Непонятно. Но если вдруг кому-то захочется продолжить копать в сторону .NET Core, дебаггинга и Linux, то определённо стоит посмотреть, что он ещё написал.
Огромное спасибо за статью, скажите пожалуйста, вы не будете против если я ваши наработки буду использовать в своем докладе https://speakerdeck.com/slach/sampling-profiling-ghlazami-obychnogho-proghrammista?
Пожалуйста.
Да, без проблем