Большинство наших приложений .Net/Java имеют функции ведения журнала. Более того, для старых полуустаревших приложений (со множеством нетривиальных условий внутри) производственные логи крайне важны для эффективной поддержки.
Несмотря на важность быстрой трассировки, я обнаружил, что многие программы имеют одни и те же очевидные ошибки. Эта статья о мире .Net, однако я также добавил код Java.
Распределение памяти
Самая распространенная ошибка (по моим наблюдениям) — пренебрежение избеганием создания ненужных объектов. Например, давайте подробно рассмотрим часто используемый метод log.Debug(…).
Общий код .Net:
Я работал с log4net и NLog большую часть времени, поэтому использую их для примера.
И вопросы:
- Какие строки выделяют новые объекты, даже если режим отладки отключен?
- Если память выделена, то как это узнать с помощью анализатора памяти (например — dotTrace)?
Правильный ответ на первый вопрос: память не выделяется только на шестой строке. И ответьте на следующий вопрос: слишком сложно найти это (в обобщенном виде), потому что такой код разбросан по всему проекту. Таким образом, вы не можете найти строку с большим количеством аллокаций, потому что у вас много одного и того же кода, который выполняет одни и те же операции (например, создает новые объекты). Просто вспомните свои старые типовые .Net проекты — с большой долей вероятности у вас есть такой же код, который грузит сборщик мусора ниже нормы.
Однако давайте глубоко проанализируем наш пример, чтобы понять, где мы влияем на производительность.
Первая строка:
После нажатия клавиши F9 (или Ctrl-B) компилятор генерирует что-то вроде этого:
Итак, наша первая строка просит процессор создать новую строку и поместить ее в регистратор. Затем библиотека трассировки проверяет, что отладка отключена, поэтому она не выполняет операций ввода-вывода. Однако новый объект находится в памяти до следующего GC. После копирования-вставки (наиболее производительной разработки приложений, по некоторым мнениям) такое поведение применяется ко многим классам, поэтому приложение просто работает медленнее. Повсюду.
Второй пример немного эффективнее, потому что вы не выделяете память для новой строки:
Однако вы все равно создаете объект в куче. Причина в боксе. Просто для восстановления подписи DebugFormat:
Как видите, здесь можно использовать только ссылочный тип. Однако мы пытаемся использовать тип значения int (или System.Int32). Поэтому каждый вызов приводит к созданию нового объекта в куче id. А нужно просто вызвать метод, который ничего не делает.
Следующий пример проще для обнаружения потенциального распределения:
Я думаю, вы понимаете, что эта строка выше будет выделять новую строку из-за неявного вызова string.Format. Однако следующий пример выглядит более эффективным:
И это так, однако давайте посчитаем, сколько объектов нам нужно выделить:
- Оператор email.Normalize() выглядит так, будто следует за новым выделением объекта. Таким образом, новая строка (или объект) выделяется в куче или в стеке (последнее возможно из-за JIT-оптимизации). Однако это не имеет значения, потому что объект выделен (то же самое с предыдущими примерами).
- id уходит в кучу из-за бокса. Мы наблюдали это выше.
- Log4net имеет следующий интерфейс для таких методов: void DebugFormat(string format, params object[] args). Как видите, .Net создает новый массив в куче (разумеется, неявно) для вызова метода DebugFormat. И так же, как и выше, массив создается в вашем методе, а не в библиотеке log4net. И снова эти выделения распределяются по приложению. И это оскорбительно, потому что обычно вы отключаете логирование в продакшене (и не включаете аллокации).
Однако давайте проверим другую библиотеку логирования — NLog.
То же самое с log4net, в строке ниже требуется новый объект в куче:
Однако строка ниже не имеет этого недостатка:
Причина в специальном методе для первого параметра int в NLog: void Debug(строковое сообщение, аргумент int). Кроме того, если вы используете struct, NLog использует общий метод void Debug‹TArgument›([Localizable(false)] строковое сообщение, аргумент TArgument). И для этого не нужен бокс, т.к. JIT создает для каждого типа отдельную функцию (формально это не совсем так, но основная причина — бокс не нужен).
Пропустим простой пример с огромной строкой ввода и проверим следующее:
NLog не имеет специального универсального события метода для четырех параметров, поэтому используется эта сигнатура void Debug([Localizable(false)] string message, params object[] args). А для этого требуется размещение объектов в куче и т. д.
Сводка
Важный момент: если в вашем приложении много методов логирования, которые не приводят к физической операции ввода-вывода, вы можете разместить в куче много ненужных объектов. И ваше приложение работает медленно из-за этого.
Еще один момент: если вы выбрасываете методы логирования с менее чем четырьмя параметрами, то просто используйте NLog. Он имеет специальные общие параметры, которые предотвращают ненужные выделения.
Однако, чтобы быть в полной безопасности (для действительно огромных методов), лучше использовать что-то вроде этого:
Как видите, лог-методы здесь не вызываются, если это не нужно. Однако, если вы хотите сбросить данные в журналы, тогда используется удобная интерполяция строк. Внутри логгеров есть оптимизация для помещения этой строки прямо в Stream, что помогает избежать аллокаций. Однако операция ввода-вывода потребляет ресурсы (но в отдельном потоке для NLog).
Пример языка Kotlin
Просто чтобы показать пример из другого стека, я хотел бы продемонстрировать интересную технику из языка Kotlin. Идея основана на небольшой языковой способности: встроенные методы. Итак, простой код, чтобы добавить что-то в журнал отладки:
Метод debug помечен как встроенный, поэтому наш код преобразуется примерно в такой вид:
Все внутри фигурных скобок — это лямбда. Он встроен во внешний метод, поэтому не выделяется в куче. Кроме того, вы можете скрыть ресурсоемкие операции внутри блока логирования. И вызываются они только в том случае, если операция ввода-вывода действительно нужна. Например:
Здесь getIdList вызывается, только если включен регистратор. И это потому, что метод преобразуется в:
Большой объект ==› Куча больших объектов
Как вы знаете, в .Net/JVM есть термин «куча больших объектов». В Java нет констант для них, однако большинство аллокаторов создают такие объекты в последнем поколении (чтобы избежать частого GC из-за таких объектов). Это работает медленно для распределения, но помогает сборщику мусора.
Вернемся к нашему примеру:
Давайте представим, что объект id имеет реализацию ToString, которая создает строку с миллионом символов (например, размер String составляет около 1 Мб). Затем появляются следующие распределения LOH:
- Вызов ToString
- Форматирование $”Id={id}”
- Если разработчики библиотеки логирования не ловят все одинаковые элементы (которые, конечно, очень трудно обнаружить), то логгер также добавляет новые проблемы.
И здесь вы можете использовать один из следующих методов, чтобы избежать таких выделений:
- Используйте специальный макет, который не требует вызова ToString. Например, в NLog есть JsonLayout. И использование такое же: вы можете просто добавить новый объект в регистратор, например: logger.Debug(id).
- Вы можете записать в файл вручную. Другими словами — избегайте использования логгеров для таких операций. Вы можете получить имя файла регистратора, используя что-то вроде этого: var filePath = NLog.LogManager.Configuration.AllTargets.OfType‹FileTarget›().First().FileName.Render(LogEventInfo.CreateNullEvent()). Очевидно, что эта функция возвращает первый FileTarget, однако, если все ваши логгеры пишут в одну и ту же папку, вы можете получить его, проанализировав любой FileTarget.
- Некоторые библиотеки протоколирования имеют специальную конструкцию, позволяющую избежать вызовов ToString. Например, log4j2 из мира java имеет интерфейс StringBuilderFormattable. У него есть специальный метод (пожалуйста, смотрите сигнатуру ниже), который вызывается, чтобы избежать выделения сплошных блоков.
Заблокированное и неблокированное ведение журнала
Однажды я обнаружил, что приложение тратит около 50% времени на операции логирования (только при интенсивной работе). Так что программа работала в два раза медленнее, чем было возможно, из-за методов logger.Debug и чего-то в этом роде. А причина была в синхронности библиотеки log4net, которую мы использовали.
После этого случая я обнаружил самое важное правило логирования: операции ввода-вывода должны работать в другом потоке. Вы не должны блокировать свое приложение для отслеживания операций. Например: всегда устанавливайте async=true внутри корневого тега nlog. Просто по примеру:
Если вы используете log4net — просто добавьте пересылку объектов журнала в NLog (или напишите собственное руководство AsyncFileAppender).
Logback и log4j2 из java world могут выполнять асинхронное ведение журнала. Вот сравнение производительности с их официального веб-сайта:
Однако у асинхронного логирования есть одна трудность: что делать при критических сбоях? Иногда приложение завершает работу не из-за завершения потока Main. Например, программа может выйти из-за вызова Application.Exit или Environment.FailFast, что выглядит как запах, однако может произойти. В этом случае лучше вызвать Flush перед уничтожением целевого процесса. В противном случае вы можете потерять важные данные об ошибках, связанных со сбоем приложения.
Сводка
Надеюсь, эта статья поможет вам писать быстрые приложения с удобным логированием. Я выделил только часть проблем, которые видел в различном коде. Все они не так очевидны (впрочем, не так уж и сложны).
В любом случае, у большинства приложений есть следы. Более того, по моим наблюдениям, примерно на половине занятий занимаются логированием. Таким образом, эффективное использование функций логирования влияет на все приложение, что важно (конечно, с моей точки зрения).
