Pull to refresh

Comments 22

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

А лучше не только в отдельном потоке, но еще использовать буфер, а внутри логгера сбрасывать буфер туда куда надо, хоть в файл, хоть в кафку

Да, всё верно. По факту если логгер сбрасывает данные в другом потоке, то зачастую он сбрасывает целый буфер (по крайней мере, тот же NLog так делает).

Мне во многом встречались только библиотеки log4net и NLog, а потому я буду использовать в примерах именно них.

… а стоило бы взять еще и Serilog, потому что в нем есть и best practices, и оптимизации, которые, например, первый пункт (аллокации) убирают если не полностью, то очень близко к тому.


Однако, чтобы уж совсем обезопаситься, логичнее делать так:
if (NLogLog.IsDebugEnabled)
{
NLogLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}");
}

Не надо так делать. Используйте структурное логирование, и вам потом будет намного проще разбирать информацию в вашем логе.


_logger.Debug(
  "Order created with {id} for {name} ({email}) for {amount}",
  id, name, email, amount
)

В вашем примере структурное логгирование все-таки выделит больше объектов, если Debug таки выключен, ибо:


  • email.Normalize() запросто породит объект
  • JIT вряд ли внутри логгера сделает оптимизацию в стиле "создаем StringBuilder прямо тут, вместо String Format, в него помещаем текущие объекты и передаем далее уже сформированную строку". Хотя здесь уже надо бенчмарк делать, так как много предположений.
если Debug таки выключен,

Если Debug выключен, первая строчка в методe Write приведет к пропуску всего последующего конвеера. Что, в свою очередь означает, что:


email.Normalize() запросто породит объект

… никакого email.Normalize не будет, потому что, если вы посмотрите на мой код, его там нет. Он спрятан в политику деструктуризации для объектов такого типа, которая вызывается внутри конвеера.


JIT вряд ли внутри логгера сделает оптимизацию в стиле "создаем StringBuilder прямо тут, вместо String Format, в него помещаем текущие объекты и передаем далее уже сформированную строку".

… никаких string.Format еще не произошло (и может никогда и не произойти вообще, кстати, синки не обязательно делают Format, они могут и поточную запись).

Я пока не до конца понял, покопаю еще. Однако интересно.


Я уже тут уже пообещал сделать бенчмарк на разные способы форматирования строки. Я добавлю тогда еще ваш метод (когда дойдут руки до самого измерения, конечно). Спасибо.

Осмысленно делать бенчмарк не форматирования строки, а полной операции вывода сообщения в лог.

На деле, скорее несколько:


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

Мне кажется, нет смысла делать оценку производительности синхронного логгера (ибо и так понятно, что IO операция без буферизации съест основную часть времени, а буфферизация синхронной вызывает "пропавшие строчки", когда программа ничего уже не делает, а в памяти самые последние записи в лог, которые будут сброшены непонятно когда).


И плюс у меня есть вопросы к разным стилям логгирования:


  • Мало или много аргументов
  • Reference/Value типы
  • Размер аргументов (т.е. для строк в 100 Кб опасно любое дополнительное форматирование посередине)
  • Разное форматирование:
    • Создать неподготовленный StringBuilder и передать его (т.е. ToString вызовется только если совсем надо)
    • Сделать строку заранее (безо всяких оптимизаций)
    • Использовать форматированную строку в стиле string.Format
    • Использовать структурное логгирование

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

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

Есть, потому что люди регулярно им пользуются.


буфферизация синхронной вызывает "пропавшие строчки", когда программа ничего уже не делает, а в памяти самые последние записи в лог, которые будут сброшены непонятно когда

Explicit disposal.

Есть, потому что люди регулярно им пользуются.

Я уже делал, результаты тут: https://habr.com/en/post/456488/


Explicit disposal.

А можно пример использования с NLog/log4net/Serilog? Т.е. чтобы можно было бы вызвать logger.Debug, однако не забывая сделать Dispose()?

А можно пример использования с NLog/log4net/Serilog?

Log.CloseAndFlush()


В более сложном приложении — положить логгер в контейнер, контейнер подиспозить на закрытии приложения.

контейнер подиспозить на закрытии приложения

Нет, надо немного другое. При буфферизации необходимо не забывать сбрасывать этот самый буфер. Однако это сделать сложно, если у вас:


  • Логгеры инициализируются как статические переменные (что довольно распространено)
  • Логгеры размазаны по приложению, причем их вызовы ограничиваются Debug/Info/Warn/Error методами.
  • В приложении нет явного контекста операции (для простоты — много подписок с broadcast), плюс присутствуют также длительные вещи (когда крайне бы хотелось иметь периодический сброс на диск, чтобы таки видеть, что там с системой).

Если используется синхронный логгер, то пока там явно не вызовется Flush, в памяти могут оставаться строчки. И в этом случае зачастую непонятно, что там было в самый последний момент (т.е. где таки программа сейчас тупит так явно). Асинхронный логгер не обладает таким минусом, так как он периодически всё отправляет на диск.


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


Однако это всё лирика, примерные направления будущих замеров я набросал выше.

При буфферизации необходимо не забывать сбрасывать этот самый буфер. Однако это сделать сложно, если у вас

Для бенчмарков это все не очень важно.


Асинхронный логгер не обладает таким минусом, так как он периодически всё отправляет на диск.

Это, кстати, совершенно не обязательно.


Плюс странно использовать синхронное логгирование, так как к каждой операции добавляется еще время сброса данных логгера на диск.

Ничего странного, если мы хотим реально получать информацию о происходящем, а не надеяться, что она когда-нибудь к нам может быть дойдет.

Для бенчмарков это все не очень важно.

Мне важно то, что прямо или косвенно влияет на скорость работы более-менее реального приложения. Если нет сброса на диск, то для меня это сферически конь, который не так интересен.


Это, кстати, совершенно не обязательно.

Ну мы же говорим о корректной конфигурации, которая имеет смысл. И в ней (по моему опыту) логичнее раз в N секунд сбрасывать данные на диск. А можете привести примеры, там где это будет неправильным?


Ничего странного, если мы хотим реально получать информацию о происходящем, а не надеяться, что она когда-нибудь к нам может быть дойдет.

Можно поставить задержку 0мс. Тогда она придет буквально на пару миллисекунд позже, по сравнению с синхронными операциями. И опять-таки, а можно пример, там где важны именно вот эти миллисекунды, а не скорость ответа сервера/UI?

Мне важно то, что прямо или косвенно влияет на скорость работы более-менее реального приложения. Если нет сброса на диск, то для меня это сферически конь, который не так интересен.

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


А можете привести примеры, там где это будет неправильным?

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


И опять-таки, а можно пример, там где важны именно вот эти миллисекунды, а не скорость ответа сервера/UI?

Длительная фоновая операция, где приложение может упасть на каждой записи, и важен лог по каждой записи.

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

Как он прервется для асинхронного логгирования? Буфер отправляется в другой поток (точнее, Task), а ваши потоки продолжают работать. Debug и прочие методы ведь так и так не будут ожидать IO.


Длительная фоновая операция, где приложение может упасть на каждой записи, и важен лог по каждой записи.

И где нам именно синхронная запись поможет? Всё равно ведь перед выходом надо вызвать Flush.


Можно всё-таки больше деталей, когда именно синхронное логгирование помогает (а не Flush по выходу и пр.)?

Как он прервется для асинхронного логгирования? Буфер отправляется в другой поток (точнее, Task)

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


И где нам именно синхронная запись поможет? Всё равно ведь перед выходом надо вызвать Flush.

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

Всё, я понял. Ваша задачи следующие:


  • Памяти практически нет, поэтому сбрасываем данные как можно быстрее.
  • Процессора не хватает, поэтому копим события в памяти до конца операции.

Верно (хотя похоже на конфликтующие требования)? Или есть еще детали?
Я, если честно, не встречал таких задач, чтобы они еще и решались адекватно стандартными средствами (а не самописным эффективным прибитым гвоздями логгингом).


А сколько в вашей программе времени тратится в среднем на одно такое логгирование, если не секрет?

Верно (хотя похоже на конфликтующие требования)?

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


А сколько в вашей программе времени тратится в среднем на одно такое логгирование, если не секрет?

А мы не меряли. Мы меряли, что при добавлении и включении логирования производительность не проседает более допустимого. Для Information, если я не путаю, было в пределах погрешности измерения, для Verbose, которого в проде не держим, в пределах 10% (но тут могу ошибаться).

Вы уверены что «В каких строчках будет выделяться память даже если Debug выключен?» будет тоько в случае 6, разве методы не помечены атрибутом Conditional[«DEBUG»]?
Если помечены, то по идее все вызовы будут вырезаные полностью.

Я имел ввиду — Debug выключен для этого логгера (т.е. просто в конфигурациях подобное задано). Это не опция компиляции.


Т.е. будет использован метод вроде этого:


public void Debug<T>(T value)
{
    if (IsDebugEnabled)
    {
        WriteToTargets(LogLevel.Debug, null, value);
    }
}

Если Вы хотите контролировать логгирование на уровне компиляции, то будут вот эти методы:


[Conditional("DEBUG")]
public void ConditionalDebug<T>(T value)
{
    Debug(value);
}

Итого:


  • Если вы хотите отключать логгирование в момент компиляции, то используйте ConditionalDebug, ConditionalInfo и так далее.
  • В противном случае Debug вызовы будут всегда присутствовать в вашем коде (однако вы можете включать/выключать эти уровни в конфигурации)
Sign up to leave a comment.

Articles