Медленная сборка кода с .NET Roslyn: как найти и устранить причину

.NET разработчики знают, что такое ждать сборки кода. Работать при этом невозможно: пока не увидишь, как обновится приложение, — не перейдешь к следующему шагу. А переключиться на другую задачу за это время не успеешь. Получается, если в день переписать код 5 раз, можно потерять полчаса при сборке, а то и больше.

Теперь на примере платформы автоматизации маркетинга Mindbox. Основное программное решение — это монолит на C#: несколько миллионов строк, 50 проектов, над которыми одновременно работают десятки команд. Даже сэкономленная при сборке минута выливается в кучу продуктивных человеко-часов. Поэтому, когда речь зашла о переходе всей компании на MacBook в будущем, мы решили выяснить, как это отразится на производительности.

Сравнили скорость сборки кода на MacBook Pro и Dell XPS. Использовали .NET SDK 7.0.100-rc.2, условия эксперимента задали с помощью двух команд:

# Удаляет все файлы и папки, которые Git не отслеживает.
git clean -fxd

# Восстанавливает все пакеты в решении без использования фоновых процессов сборки (воркеров), так как их кэш может влиять на время сборки.
# Аргумент --disable-build-servers доступен начиная с .NET 7.
dotnet restore --disable-build-servers

Чтобы измерить время сборки проекта, использовали команду:

# Собирает решение без запуска фоновых воркеров, пропуская этап восстановления пакетов.
dotnet build --no-restore --disable-build-servers

Оказалось, MacBook втрое проигрывает по производительности:

После такого результата мы начали расследование: проанализировали нагрузку на ядра, изучили логи, трассировали все подозрительные процессы и выяснили, где теряются 7 минут. В этой статье рассказываем, как обнаружить и победить причину медленной сборки.

Проблема не в процессоре: три ошибочных гипотезы

Первая догадка была в том, что низкая производительность процесса сборки на MacBook связана с недостатками процессора.

Гипотеза 1. Производительности CPU недостаточно для быстрой сборки на MacBook. Это предположение легко проверить с Activity Monitor — утилиты, которая показывает нагрузку на каждое ядро в процессоре:

На графике выше видны редкие пики нагрузки, когда используются все 10 ядер. Но в основном третье и четвертое на двоих выполняют системный код, достаточный, чтобы занять целиком одно ядро. Получается, оно постоянно в работе, хотя и не участвует в сборке кода. Между тем 6 ядер вполне свободны, а значит, производительность CPU не является проблемой.

Гипотеза 2. Процессор производит компиляцию на энергосберегающих ядрах. Процессор в MacBook M1 Pro использует архитектуру ARM с технологией big.LITTLE. Эта технология делит все ядра процессора на два типа – энергосберегающие и производительные. Можно предположить, что производительность падает из-за работы компилятора на энергосберегающих ядрах. Но этот вариант отпадает: на предыдущем графике видно, что основная нагрузка делится между двумя производительными ядрами (Performance).

Гипотеза 3. .NET плохо оптимизирован для процессоров на архитектуре ARM. Чтобы проверить, влияет ли ARM на производительность, мы провели несколько экспериментов. На момент тестирования поддержка macOS на ARM рантаймом .NET была достаточно свежа, и в ней регулярно находили недостатки.

Для начала протестировали поведение при использовании виртуальной машины Windows под ARM. Виртуальной машине были выделены 6 ядер и 8 ГБ ОЗУ. Результат в сравнении с MacBook:

Даже с меньшим числом ядер Windows проводит сборку вдвое быстрее, чем macOS.

Вероятно, проблема в специфике macOS, запущенной на ARM. Чтобы это выяснить, мы протестировали сборку на MacBook Pro 16" (2019/i9 8-core/16GB) с процессором Intel и на виртуальной машине Windows с тем же Intel, для которой выделили 4 ядра и 6 ГБ ОЗУ. Результаты:

Выходит, процессор роли не играет — проблема с производительностью специфична для macOS.

Анализ логов MSBuild: ошибка в процессе сборки

Когда все связанные с процессором гипотезы были опровергнуты, оставалось искать проблему в самом процессе сборки, то есть в логах.

MSBuild детально описывает каждое выполненное действие, если выставить уровень логирования (verbosity) в аргументах командной строки на detailed или diagnostic. Однако такие логи зачастую неудобно анализировать: там смешиваются события разных воркеров, работающих параллельно. Полученный файл может весить сотни мегабайт и в нем трудно что-либо найти. Помогает binlog (он же structured log) — лог, записанный в бинарном формате и структурированный по типам и очередности событий. Он распутывает поток логов от разных воркеров, но это не единственный плюс binlog в сравнении с текстовым логом:

• он легче в 10–20 раз;

• меньше влияет на скорость сборки;

• может конвертироваться в текстовый лог при необходимости.

Подробнее о binlog — в документе Microsoft

Чтобы записать binlog во время сборки, достаточно передать аргумент -bl:

dotnet build -bl ...

Анализировать такие логи можно в программе MSBuild Structured Log Viewer. Есть версия на WPF (Windows Presentation Foundation) для Windows, кроссплатформенная на фреймворке Avalonia и даже онлайн-версия на Blazor. Однако просмотреть таймлайн на данный момент можно только в WPF-версии, а это важно: иначе не вычислить, в какой момент и на какой операции замедляется сборка.

Binlog сборки записывается командой dotnet build -bl --no-restore --disable-build-servers в папке со всеми проектами решения. Там же появляется файл msbuild.binlog со всей записанной информацией. Его нужно открыть в программе MSBuild Structured Log Viewer, перейти в папку с десятью самыми времязатратными задачами и просмотреть, сколько они выполнялись.

Во вкладке Tracing по секундам отображается, чем был занят каждый воркер. Отфильтруем все ненужное, оставив только отображение выполняемых задач:

Как видно, большую часть времени исполняется только одна или две задачи одновременно и они в среднем длятся по минуте. Непонятно, почему данные задачи выполняются настолько долго. Чтобы это выяснить, проанализировали одну из таких задач и попытались найти параметр, который замедляет сборку кода, но безуспешно.

При беглом просмотре параметров, переданных компилятору, очевидно, что они ничем не отличаются от параметров сборки в другом окружении. Но в таком случае неясно, почему компилятор ведет себя иначе в другой ОС. Нужно проследить за его поведением.

Результаты трассировки: проблема — в системном вызове

Наблюдать за поведением компилятора можно при помощи трассировки уже запущенных процессов сборки с инструментом dotnet-trace. Команда dotnet build запускает по воркеру на каждое ядро процессора, а значит, нужно собирать трейс с каждого из 10 процессов. Запустить саму сборку через dotnet-trace не получится, так как инструмент будет записывать трассировку только для основного процесса, исключая все воркеры. Чтобы трассировать процессы воркеров, в dotnet-trace нужно вручную указывать ID каждого из них. Это можно автоматизировать с помощью скрипта:

for pid in $(pgrep dotnet)
do
	dotnet trace collect -p $pid -o $pid.nettrace --duration 00:00:00:15
done

Так можно выполнять фоновую запись трейса на протяжении 15 секунд — этого достаточно, чтобы отследить методы и выявить ошибку, если она есть. 

Записанные трейсы нужно сконвертировать для анализа. В dotnet-trace для конвертации файлов есть команда convert, которой мы воспользуемся в следующем скрипте для конвертации всех трейсов в текущей папке:

for i in *.nettrace
do
	dotnet-trace convert --format speedscope $i
done

dotnet-trace поддерживает несколько форматов — мы выбрали Speedscope. Speedscope – онлайн-утилита для визуализации трейсов в виде флеймграфов. В каждом трейсе есть информация о тредах процесса и о том, какой метод в какой момент времени исполнялся в каждом треде. Просматривая трейс за трейсом и тред за тредом, находим любопытный тред:

Как видно по вызовам в верху стека, тред запускает Roslyn-анализаторы при компиляции. Roslyn — это платформа компилятора .NET, которая предоставляет SDK и API, чтобы расширять функционал компилятора. Roslyn позволяет писать кастомные анализаторы, которые указывают разработчику ошибки в коде или выводят предупреждения.

На скриншоте треда видна необычная закономерность. Зеленым выделено время работы самописного анализатора Mindbox. В идеале оно должно занимать пару секунд, а по факту растягивается почти на минуту. Этого не видно, потому что мы прервали сборку на 12-й секунде — иначе на иллюстрации было бы слишком много лишних тредов. Что еще интереснее, сборка надолго уходит в неуправляемый код — эти отрезки времени показаны бордовым. Причину мы пока не выяснили, но полагаем, что сборка задерживается именно на этом этапе.

Анализатор, который замедляет выполнение кода, – это Mindbox.I18n.Analyzer, специально написанный для проверки ключей локализации. Код нашего фреймворка для локализации — в открытом доступе.

Анализатор создает инстанс FileSystemWatcher для каждого из файлов локализации и файлов проекта, чтобы отслеживать любые изменения в них. Как только FileSystemWatcher обнаружил изменение, он сигнализирует об этом анализатору. Тот сканирует файлы локализации, выявляет новые или удаленные ключи и на основе этого указывает ошибки в коде или выводит предупреждения. Для разработчика это удобно тем, что уменьшается время цикличный процесс, когда результат, полученный после изменений кода, служит основой для последующих изменений</p>" data-abbr="feedback loop">feedback loop: он замечает ошибку и корректирует код еще до запуска автоматической сборки (CI) и тестов.

Ниже — код, который отвечает за подгрузку и отслеживание изменений в файлах локализации:

private void LoadLocalizationFiles(IEnumerable<string> localizationFiles)
{
	foreach (var localizationFile in localizationFiles)
	{
		var watcher = new FileSystemWatcher
		{
			Path = Path.GetDirectoryName(localizationFile),
			Filter = Path.GetFileName(localizationFile),
			IncludeSubdirectories = false,
			NotifyFilter = NotifyFilters.LastWrite | NotifyFilters.FileName
		};

		watcher.Changed += (s, ea) => HandleLocalizationFileChange(localizationFile);
		watcher.Renamed += (s, ea) => HandleLocalizationFileChange(localizationFile);

		if (_localizationFileSystemWatchers.TryAdd(localizationFile, watcher))
		{
			watcher.EnableRaisingEvents = true;
		}
		else
		{
			watcher.Dispose();
		}
	}
}

В этом фрагменте кода встречается метод LoadLocalizationFiles, который, по данным Speedscope, замедляет работу анализатора Mindbox, а следовательно, и сборку кода.

При выставлении EnableRaisingEvents = true запускается метод StartRaisingEvents, который начинает отслеживание изменений. Это, опять же, видно на Speedscope. Для каждой ОС — своя реализация этого метода, а значит, на macOS и Windows он выполняется по разному.

Ниже — фрагмент свойства EnableRaisingEvents из стандартной библиотеки .NET:

/// <devdoc>
///    Gets or sets a value indicating whether the component is enabled.
/// </devdoc>
public bool EnableRaisingEvents
{
    get
    {
        return _enabled;
    }
    set
    {
        // [опущено для краткости]

        if (value)
        {
            StartRaisingEventsIfNotDisposed(); // will set _enabled to true once successfully started
        }

        // ...
    }
}

По стэку вызовов видно, что после StartRaisingEvents последний вызов в управляемом коде находится в RunningInstance.Start(). Вот как выглядит его исходный код для macOS:

internal unsafe void Start(CancellationToken cancellationToken)
{
    // ...
    try
    {
        // Get the path to watch and verify we created the CFStringRef
        path = Interop.CoreFoundation.CFStringCreateWithCString(_fullDirectory);

        // ...

        // Take the CFStringRef and put it into an array to pass to the EventStream
        arrPaths = Interop.CoreFoundation.CFArrayCreate(new CFStringRef[1] { path.DangerousGetHandle() }, (UIntPtr)1);

        // ...

        // Make sure the OS file buffer(s) are fully flushed so we don't get events from cached I/O
        Interop.Sys.Sync();

        // ...
    }

    // ...
}

Ранее, когда мы анализировали нагрузку на CPU через Activity Monitor, то заметили, что одно ядро постоянно занято системным кодом. То есть нагрузка обусловлена системными вызовами к ядру ОС. Теперь мы их отследили. Первые два вызова, CFStringCreateWithCString и CFArrayCreate, отвечающие за создание объектов — не выглядят хоть сколько-либо тяжелыми. Поэтому обратим внимание на вызов Interop.Sys.Sync(). Данный метод вызывает другой метод из нативной части рантайма .NET, тело которого состоит из единственного вызова — sync().

sync() — это системный вызов Unix, который синхронизирует с диском все изменения файлов, сохраненные в памяти, при этом полностью блокируя системный I/O. Обычно он используется, чтобы данные не потерялись при резком отключении устройства. В нашей ситуации sync должен предотвратить получение событий FileSystemWatcher’ом , которые произошли до начала отслеживания изменений. Мы были уверены, что проблема именно в этом вызове, но решили проверить — опять же с помощью трассировки.

Если вы трассировали системные вызовы в Linux, то наверняка знаете, что для этого используется утилита strace. Однако ее не существует в Darwin — ОС на базе спецификации Unix, на ядре которой основана macOS. Несмотря на то, что у Linux и Darwin общий прародитель — Unix, развивались они разными путями. Одна ОС произошла от GNU, а вторая — от BSD.

Как потомок BSD, macOS унаследовала множество утилит. В том числе и dtruss: это аналог strace, который позволяет динамически трассировать системные вызовы. Подробнее об утилитах strace, ptrace, dtrace, dtruss и их различиях можно прочитать в англоязычной статье.

Итак, с помощью dtruss трассируем вызовы во время сборки, чтобы проверить свою гипотезу. Записать выполненные системные вызовы при сборке решения можно командой:

sudo dtruss -ef -t sync dotnet build --no-restore --disable-build-servers 2> log-dtruss.txt
# Флаг -f позволяет автоматически трассировать потомков процесса;
# -e выводит общее время в микросекундах, потраченное на вызов;
# -t фильтрует все системные вызовы, кроме sync().

Использование dtruss на macOS может требовать отключения System Integrity Protection, как это сделать можно прочитать в документации Apple.

После сборки получаем файл log-dtruss.txt с полным выводом утилиты dtruss, а также stdout самого dotnet build. Отфильтровываем лишние строки из файла с помощью grep, форматируем, как нам удобно, и представляем в виде гистограммы:

Так как все вызовы sync происходят последовательно, мы суммировали их длительность и узнали, сколько времени они отнимают. В сумме на 5271 вызов sync было затрачено приблизительно 7 минут. Это и есть разница между временем сборки кода на macOS и Windows, где нет проблемы с sync.

Решение: как ускорили сборку кода

Мы нашли решение, не меняя исходный код рантайма, и смогли ускорить сборку кода на MacBook Pro с 10 минут до трёх. Чтобы анализатор Mindbox работал быстрее, в его коде сократили инстансы FileSystemWatcher с нескольких сотен до одного. Теперь инстанс создается не на каждый файл локализации, а на всю папку, где они хранятся. Анализатор видит сразу все изменения в файлах локализации и фильтрует лишние события на уровне кода.

Ниже — исправленная часть кода анализатора: 

private void CreateTranslationFileChangeWatcher(string solutionDirectory)
{
   _translationFileChangeWatcher = new FileSystemWatcher
   {
       Path = solutionDirectory,
       Filter = $"*.{TranslationFileSuffix}",
       IncludeSubdirectories = true,
       NotifyFilter = NotifyFilters.LastWrite
   };
 
   _translationFileChangeWatcher.Changed += (_, ea) => HandleLocalizationFileChange(ea.FullPath);
   _translationFileChangeWatcher.EnableRaisingEvents = true;
}

Проверили — такой подход действительно ускоряет сборку до 3 минут:

Build succeeded.
    0 Warning(s)
    0 Error(s)
Time Elapsed 00:03:00.67

Чтобы глобально решить проблему медленной сборки из-за вызова sync, мы завели issue в репозитории .NET рантайма. Однако Microsoft пока не ответил. Тем временем мы просмотрели код методов для других платформ в том же репозитории. Оказалось, вызов sync() в них не используется вообще. Так что, возможно, простой способ ускорить сборку — просто не делать соответствующий вызов. Правда, в теории это может вызвать проблемы из-за кэша, но будут ли они на практике – неизвестно.

Советы и полезные ссылки, которые помогут найти причину медленной сборки

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

1. Можно поискать задачи, которые замедляют сборку, в логах MSBuild. Лучше всего подойдет binlog (он же structured log) — лог, записанный в бинарном формате и структурированный по типам и очередности событий. В программе MSBuild Structured Log Viewer можно даже проверить параметры, переданные компилятору, — возможно, какой-то из них замедляет сборку.

2. Если не нашли в логах энергоемких задач, трассируйте сборку и ищите методы, которые выполняются подозрительно долго. Удобнее всего трассировать процессы компилятора с инструментом dotnet-trace. Затем рекомендуем визуализировать трейсы в Speedscope: на флеймграфах будет отчетливо видно, какие методы выполняются дольше всего. В нашем случае это оказался метод StartRaisingEvents, который по-своему реализуется для каждой ОС и выполняется с разной скоростью на macOS и Windows.

3. В коде подозрительных методов ищите тяжелые для обработки системные вызовы, если наблюдаете высокую нагрузку кодом ядра ОС. Эти вызовы можно трассировать в процессе сборки с помощью утилиты dtruss на macOS или strace на Linux. Если представить лог в виде гистограммы, будет видно, сколько вызовов выполнено при сборке и сколько времени они заняли. В нашем случае вызов sync() от самописного анализатора Mindbox отнимал ~7 минут при сборке.

Сервисы и утилиты, которые могут пригодиться:

• MSBuild Structured Log Viewer — для анализа логов в формате binlog. Советуем WPF-версию для Windows: только у нее есть таймлайн, где можно отследить, в какой момент и на какой операции замедляется сборка.

• Dotnet-trace — чтобы трассировать уже запущенные процессы сборки.

• Speedscope – для визуализации трейсов в виде флеймграфов. Поможет обнаружить методы, которые выполняются слишком долго.