Бескультурная сказка про Dottrace

Короткая зарисовка о том, почему важно осознанно писать каждую строчку кода, каждый символ. А заодно и небольшой мастер-класс по использованию dottrace и класса string одновременно.

Художественное отступление, шутка на текущую тему. Чтобы узнать самое интересное, читать текст под катом совершенно необязательно.

Это был поздний вечер. Прямо в офисе, когда уже никого нет и никто не помешает. Взгляд медленно двигался вдоль всего тела. Иногда он останавливался, лишь на мгновение, на привлекательных местах. А иногда взгляд застывал надолго, неприлично долго, пристально разглядывая самое интересное.

Сосредоточенный взгляд, прикушенная губа, все тело замерло, лишь чуть-чуть шевелятся пальцы. Очевидно, что этот процесс доставляет удовольствие, полностью увлекает.

— Фу, что это за культура! — неожиданно раздалось на весь openspace.

Лицо неодобрительно искривилось. Во взгляде появилось пренебрежение и недовольство.

— Ну кто опять написал сравнение строк с InvariantCulture там, где это не требуется! И ведь прямо посреди тела этого важного метода!

Поздний вечер. В офисе уже никого нет. Чем же заняться? Конечно же, снимать трейс с какого-нибудь приложения и анализировать его. Пусть будет Snitch.Enricher. А то чего это он аж 80 ядер потребляет в пиковые по нагрузке дни! И в этот раз в качестве трейса будет dottrace timelime. Люблю именно timeline’ы при анализе CPU.

Заходим в консоль, вводим команду dottrace attach <pid> --profiling-type=Timeline.

Время решать головоломку. У нас целых 30 секунд таймлайна с одной реплики Snitch.Enricher и желание уменьшить его потребление CPU.

Открываем трейс и видим вот такую картину:

Слева мы видим менюшку, где можно выбрать, что мы будем изучать. Not Selected — это «времена», потраченные всеми тредами в определённых стеках (и функциях). Время — это ещё и CPU в тех методах, которые не ждут чего-то, а выполняют полезную работу. Именно это нам сейчас и нужно.

Сверху по центру мы видим окно «Hotspots». Это те методы, которые чаще всего были на вершинах стеков всех потоков в течение всего времени, что мы записывали трейс. Отличная группировка, спасибо dottrace, мы ей воспользуемся.

Hotspots

Очевидно, что здесь много мусора: ожидающих и ничего не делающих методов. Это всё, что со словами Wait, Sleep, … Они потребляли только время, а не CPU. Их надо убрать. Я подсветил их жёлтым:

Да, можно встретить ситуацию, когда эти «ожидания» на самом деле потребляли существенное количество ресурсов. Но они крайне редки и начать исследования с их исключения стоит почти всегда. Кликаем правой кнопкой, жмём Exclude method.

Смотрим, что осталось. В топе хотспотов все ещё много чего-то неприятного:

Thread pool

Первый в списке — метод из тредпула. Верим ли мы, что тредпул потратил 59% нашего CPU? Скорее нет, чем да, ведь никаких других намёков на проблемы с тредпулом у нас нет (впрочем, бывает всякое 😉). Приложение стабильно потребляет 2-10 воркертредов. Открываем код, смотрим на метод PortableThreadPool.WorkerThreadStart(), и там буквально первая строчка — semaphore.Wait().

Да, там возможны SpinWait’ы. Но логично предположить, что чаще всего приложение проваливается в полноценное ожидание в этом месте.

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

Sockets

Третий в списке метод — метод из сокетов, цикл, ожидающий работу. Открываем код метода SocketAsyncEngine.EventLoop(), и там буквально первая строчка — Interop.Sys.WaitForSocketEvents(). Верим ли мы, что наше приложение очень активно общается с кем-то по сети? Скорее нет, чем да, мы знаем, что Snitch.Enricher — это буквально однопоточная числодробилка, читающая один сетевой стрим, и пишущая результат в другой.

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

Изучаем новый топ хотспотов:

Native stack traces

А вот тут уже интересно! В топе какие-то нераспознанные стеки: Native stack traces without resolved functions. Обычно, это время (а значит, может быть и потребление CPU, и ожидания), проведённое где-то в системных функциях, распарсить которые dottrace не в силах. Ну и черт с ними. Ниже первой строчки уже выделяются очень интересные вещи.

Посмотрите на вторую строчку. Это метод из недр дотнета, а не нашего кода, поэтому он покрашен в серый цвет (а не черный). В классе CompareInfo такой метод и правда есть. Смотря на него, сразу верится, что этот метод действительно потребляет CPU.

Hotspots.Usages

Двинемся дальше по возможностям dottrace. Посмотрим, кто вызывал этот метод!

Ага, все дороги ведут в методы ProcessHttpSpan или ProcessCustomSpan из класса SpanReaderWriter. Либо напрямую, либо транзитивно через Normalize и IsError. Неплохое сужение диапазона поиска. Но в целом, ничего удивительного. Эти методы — основная работа приложения. На каждый элемент (спан), вычитанный из стрима, вызывается один из методов ProcessXXXSpan. Отправляемся в код!

Если бы вы открыли код SpanReaderWriter.ProcessHttpSpan и очень внимательно его прочли, то вы бы не нашли ничего про хешкоды от строк. В методах ProcessCustomSpan, Normalize и IsError — тоже.

Почему же так случилось? Инструменты записи и анализа трассировок анализируют приложение после того, как его сконвертировали в JIT-код (а по пути соптимизировали), а затем JIT-код был скомпилирован (и соптимизирован) в ассемблер. И одна из частых оптимизаций — inlining. Это когда тело вызываемого метода встраивается целиком в тело вызывающего. Делается так из-за того, что вызов метода — относительно дорогая инструкция. А значит в трейсе, в дереве вызовов, мы можем видеть те методы и инструкции, которые вызывались на сколько угодно глубже по C#-коду. И то, что мы видим вызов метода IcuGetHashCode внутри метода ProcessHttpSpan, значит лишь то, что где-то на любой глубине в цепочке вызовов внутри ProcessHttpSpan, был IcuGetHashCode.

Можно отправиться читать ВЕСЬ код внутри ProcessHttpSpan, все вызовы методов, даже системные, чтобы найти место, где вызывают GetHashCode от строк. Но это самый последний и достаточно дорогой способ. А пока, попробуем применить дедукцию!

Дедуктивный метод

Раскладываем строчку System.Globalization.CompareInfo.IcuGetHashCodeOfString(ReadOnlySpan, CompareOptions)на ключевые слова:

HashCode от строчки — есть, очень важно.
CompareOptions, потенциально с опциями про IgnoreCase — запоминили.
Класс CompareInfo оперирует CultureInfo, да ещё и из неймспейса System.Globalization — возможно важная деталь, это про всякие InvariantCulture.
Как часто в коде берут хеш от строк? Ну бывает, но это всё-таки редкость. Куда чаще их складывают в коллекции, например HashSet или Dictionary, в качестве ключа.

Значит, надо искать что-то, что часто берёт хеш-код от строк, потенциально с опциями про IgnoreCase и культуру? Вероятнее всего, это хеш-сет или словарь!

Call Tree

Вкладка Hotspots, на самом деле, всего-лишь вспомогательная. Что ещё можно извлечь из трейса? Можно обратить внимание на нижнюю (и, на мой взгляд, основную) часть, которая называется Call Tree. Так она выглядит после того, как мы исключили из рассмотрения все неинтересные нам функции:

Да, увы, для многопоточного приложения, активно использующего тредпул, дерево вызовов очень неудобное. По сути, мы можем встретить столько разных деревьев, сколько асинхронных методов в нашем коде. Потому что «дерево вызовов» начинается каждый раз с тредпульного метода ThreadStart(), а дальше любой другой асинхронный метод, перед которым стейтмашина прерывалась на настоящее асинхронное ожидание.

Но им всё равно можно пользоваться. Можно рассмотреть несколько цепочек из топа. Так, развернув самый верхний, в данном случае видим вот такое (да, я прокликал «развернуть» на каждой открывающейся строчке, пока не добрался до самого низа):

Да, мы видим здесь подтверждение нашей гипотезы. ProcessHttpSpan где-то глубже по стеку вызывает FindValue на словаре, который вызывает GetHashCode, который вызывает IcuGetHashCodeOfString. Но, опять же, тут пропущены все промежуточные вызовы методов.

Ищем в коде

Посмотрим, есть ли у нас использования HashSet или Dictionary с какими-нибудь StringComparer. Как это выглядело бы в коде?

var dictionary = new Dictionary<string, string>(StringComparer.xxx);

Я поискал использования StringComparer у нас в коде. Это довольно легко — напишите где-нибудь StringComparer и нажмите хоткей по поиску использований.

Я не буду показывать скриншот поиска по солюшну, потому что он нашёл довольно много использований в проектах, от которых Snitch.Enricher не зависит. А также часть использований были в тех методах, которые очевидно не влияют на наши ProcessHttpSpan и ProcessCustomSpan. Мне понадобилось отфильтровать примерно десяток использований StringComparer, которые нам не интересны. Сделал я это относительно легко благодаря знанию устройства проекта.

И мне очень повезло. Остался всего один подозрительный пример:

public class PerServiceSettings<TValue> : Dictionary<string, TValue> {    public PerServiceSettings(Dictionary<string, TValue> dictionary)        : base(dictionary, StringComparer.InvariantCultureIgnoreCase)    {    } }

И к этому readonly словарю обращаются один раз на каждый вызов всех тех методов, которые нам подсветили в трейсе: ProcessHttpSpan, Normalize и IsError. Обращение — просто чтение значения по ключу.

Что не так с этим методом? Вытащить значение из словаря по ключу не может быть таким дорогим (в сравнении с кучей остальной работы, которая делается в этих методах). Глаз цепляется только за InvariantCultureIgnoreCase. Действительно, зачем нам InvariantCulture, если мы просто хотим извлечь настройки по имени сервиса? Нам не нужны никакие умляуты и китайские символы (имена сервисов состоят только из url-friendly символов). Нам не нужно запускать это на десктопах пользователей. Нам не нужно сравнивать в правильном порядке всякие буквы ё.

Байка про букву ё

Кстати, .Net6 вообще неправильно сравнивал строки, пока наш инженер М не поучаствовал в том, чтобы заставить Microsoft исправить это.

Бенчмаркаем

На сколько InvariantCulture хуже, чем Ordinal?

Вне зависимости от того, нужны нам или не нужны именно InvariantCulture сравнения, давайте все равно проверим, а что изменится, если заменить InvariantCultureIgnoreCase на OrdinalIgnoreCase?

TryGetValue

[GlobalSetup] public void SetUp() {    dictionary1 = new Dictionary<string, int>();    dictionary2 = new Dictionary<string, int>(comparer: StringComparer.Ordinal);    dictionary3 = new Dictionary<string, int>(comparer: StringComparer.InvariantCulture);    dictionary5 = new Dictionary<string, int>(comparer: StringComparer.OrdinalIgnoreCase);    dictionary6 = new Dictionary<string, int>(comparer: StringComparer.InvariantCultureIgnoreCase);    keys = new List<string>();    for (var i = 0; i < 10_000; i++)    {        var str = Guid.NewGuid().ToString();        //специально, чтобы избегать сравнения по ссылке        keys.Add(Guid.Parse(str).ToString());        dictionary1[str] = i;        dictionary2[str] = i;        dictionary3[str] = i;        dictionary5[str] = i;        dictionary6[str] = i;    } } ... [Benchmark] public int TryGetOrdinalIgnoreCase() {    var summ = 0;    for (var i = 0; i < keys.Count; i++)    {        if (dictionary5.TryGetValue(keys[i], out var value))            summ += value;    }    return summ; } [Benchmark] public int TryGetInvariantCultureIgnoreCase() {    var summ = 0;    for (var i = 0; i < keys.Count; i++)    {        if (dictionary6.TryGetValue(keys[i], out var value))            summ += value;    }    return summ; }

К результатам бенчмарка на Windows комментарии не нужны.

|                           Method |        Mean | |--------------------------------- |------------:| |                           TryGet |    370.5 us | |                    TryGetOrdinal |    353.6 us | |                  TryGetInvariant | 11,616.0 us | |          TryGetOrdinalIgnoreCase |    589.4 us | | TryGetInvariantCultureIgnoreCase | 11,547.5 us |

Ну, разве что стоит запустить такой бенчмарк не только на Windows, но и на Linux. Всё-таки извлечение культуры сильно зависит от ОС.

|                           Method |       Mean | |--------------------------------- |-----------:| |                           TryGet |   365.8 us | |                    TryGetOrdinal |   364.5 us | |                  TryGetInvariant | 9,029.4 us | |          TryGetOrdinalIgnoreCase |   580.1 us | | TryGetInvariantCultureIgnoreCase | 8,783.4 us |

Удивительно, но на Linux чуточку быстрее. Обычно наоборот. В целом, всё понятно. Вне зависимости от ОС, разница в 15-30 раз. Смело меняем InvariantCultureIgnoreCase на OrdinalIgnoreCase в нашем случае!

IndexOf, Equals

А давайте поищем ещё использования InvariantCultureIgnoreCase и InvariantCulture в солюшне? Не только у класса StringComparer, но и у StringComparison (аргумент для String.Equals и пр.).

Их нашлось два:

service.IndexOf(" via ", StringComparison.InvariantCultureIgnoreCase); ... normalizedPath.Equals(filteredPrefix, StringComparison.InvariantCultureIgnoreCase))

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

private const string service = "Kontur.что-то там via Kontur.что-то там другое"; [Benchmark] public int GetOrdinalIgnoreCase() {    return service.IndexOf(" via ", StringComparison.OrdinalIgnoreCase); } [Benchmark] public int GetInvariantCultureIgnoreCase() {    return service.IndexOf(" via ", StringComparison.InvariantCultureIgnoreCase); }

Вот результаты.

|                        Method |  Runtime |     Mean | |------------------------------ |--------- |---------:| |          GetOrdinalIgnoreCase | .NET 6.0 | 65.35 ns | | GetInvariantCultureIgnoreCase | .NET 6.0 | 72.18 ns | |------------------------------ |--------- |---------:| |          GetOrdinalIgnoreCase | .NET 7.0 | 16.10 ns | | GetInvariantCultureIgnoreCase | .NET 7.0 | 62.72 ns |

Сейчас на .Net6 нам это не сильно поможет, а вот будь мы на .Net7+, разница уже была бы приятная.

Результат

Ну окей. Заменили мы InvariantCulture на Ordinal в паре мест, которые, судя по трейсу, должны быть горячими. Осталось проверить, как это повлияло на настоящее приложение.

На графике отчетливо видно момент релиза. Кажется, успех.

Важно убедиться, что это не эффект от перезапуска и что он сохранится в течение длительного времени.

Графики говорят сами за себя.

Ну что, один час раскопок и 30 секунд написания кода, кажется, стоили ~20 сэкономленных ядер каждодневного потребления. А один раз случайно и неаккуратно выбранная культура для работы со строками стоила ~25% от потребления CPU в конкретно этом приложении Snitch.Enricher.

Как анализировать Timeline трейс в dottrace при оптимизациях CPU

Отфильтровывайте то, что вам не интересно. Чаще всего это — всякие методы со словами Wait, и прочие штуки, намекающие на ожидания.
Безжалостно исключайте то, что вам абсолютно не понятно, или что выглядит точно не как CPU-работа.
Не пренебрегайте изучением кода .Net’а на гитхабе. И других ваших зависимостей. Это часто помогает.
Будьте готовы сделать фулскан: всех использований, всего кода, и т.д. Да, это часто придётся делать, от этого никуда не деться.
Если хотспоты не помогают, не бойтесь огромного многообразия в окне Call Tree. Просто берёшь и залазишь в каждую более-менее тяжелую строчку и погружаешься до самого низа, пока разделение потребления не упрётся в один конкретный метод или не расщепится на множество небольших.
Не стесняйтесь высказывать гипотезы, а затем проверять их. Помните, трейс показывает не всю информацию, а лишь часть. Знание особенностей проекта, который вы изучаете, очень сильно поможет вам.
Проверяйте бенчмарками, что ваши гипотезы верны. В том же окружении, в котором работает ваше приложение: версии .Net’а, ОС. Это важно.
Обязательно анализируйте метрики после релиза, перепроверяйте результат.

ссылка на оригинал статьи https://habr.com/ru/articles/854340/