Типичные ошибки при логгировании

Привет, Хабр!

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

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

Аллокации (выделение памяти)

Самая распространенная ошибка (по моим наблюдениям) — это небрежность по отношению к мелким выделениям памяти возле места вызова функции log.Debug(...).

Итак, наш стандартный код в .Net:

private static readonly ILog Log4NetLog = LogManager.GetLogger(typeof(Program));
private static readonly Logger NLogLog = NLog.LogManager.GetCurrentClassLogger();

private static void PublishData(int id, string name, EMail email, decimal amount)
{
    Log4NetLog.Debug($"Id={id}"); // 1
    Log4NetLog.DebugFormat("Id={0}", id); // 2
    Log4NetLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 3
    Log4NetLog.DebugFormat("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 4

    NLogLog.Debug($"Id={id}"); // 5
    NLogLog.Debug("Id={0}", id); // 6
    NLogLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 7
    NLogLog.Debug("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 8
}

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

Итак, вопросы:

• В каких строчках будет выделяться память даже если Debug выключен?
• Если память выделяется, то насколько легко обнаружить в том же dotTrace, что конкретно логгеры виной этому самому выделению памяти?

Правильный ответ на первый вопрос: память не выделяется только в пункте "6". А ответ на второй вопрос: поймать такое невероятно сложно, так как подобный код зачастую размазан по проекту. Вы можете вспомнить типичное приложение на .Net. В нем зачастую будет похожий код, который заставляет GC работать.

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

Итак, первый пункт:

Log4NetLog.Debug($"Id={id}"); // 1

На деле компилятор преобразует её в:

var temp = string.Format("Id={0}", id); // <-- тут будет то самое выделение памяти

Log4NetLog.Debug(temp);

То есть первое выражение по сути будет заставлять процессор создавать строку, передавать её в логгер. Он же быстро проверит, что логгировать не надо, а потому строка просто создалась в памяти. И, что важно, если побольше раскопировать такой код, то строки будут создаваться в кучи мест программы, то есть программа будет работать просто немного медленнее. Везде.

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

Log4NetLog.DebugFormat("Id={0}", id);

Однако память здесь всё равно выделяется, так как будет происходить boxing. Напомню сигнатуру метода DebugFormat:

void DebugFormat(string format, object arg0)

Как видно, на вход требуется ссылочный тип. Однако мы пытаемся передать значимый тип int. В итоге каждый вызов будет приводить к вынесению параметра id в кучу, чтобы передать его в метод. И напомню, в самом методе параметр не нужен, так как Debug у нас выключен по условию задачи.

Следующий пример нагруженный и простой:

Log4NetLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 3

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

Log4NetLog.DebugFormat("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 4

И это так, однако давайте подсчитаем, сколько раз надо выделить по кусочку памяти:

• email.Normalize() приводит к созданию какого-то объекта. А потому этот объект выделится в куче (или на стеке — не важно, так как боксинг заставит выделить всё в куче)
• id уйдет в кучу, как мы уже рассматривали ранее.
• Log4net имеет следующий интерфейс для подобных длинных форматированных вызовов: void DebugFormat(string format, params object[] args). Как видно, .Net создаст массив в куче, чтобы передать его в метод DebugFormat.

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

Эта строка спровоцирует выделение объекта в куче:

NLogLog.Debug($"Id={id}");

Здесь всё очевидно, однако строка ниже уже не обладает таким недостатком:

NLogLog.Debug("Id={0}", id);

А причина в том, что NLog имеет специальную сигнатуру для int'ов: void Debug(string message, int argument). Более того, даже если передать другую структуру, то вызовется метод void Debug<TArgument>([Localizable(false)] string message, TArgument argument). И вот этот метод не требует уже боксинга, так как после JIT будет создаваться отдельная функция для каждого типа (конечно, это не совсем так, однако важна суть: боксинга не будет).

Я пропустим простой в понимании сценарий с большой строкой на входе и перейдем сразу к:

NLogLog.Debug("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount);

Как ни странно, в NLog не увеличивали число Generic параметров для методов, а потому будет использована сигнатура: void Debug([Localizable(false)] string message, params object[] args). И она опять приведет к созданию объектов в кучи и так далее.

Выводы и улучшения

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

Вывод 2: Если Вы передаете не так много объектов в метод, то используйте NLog. За счет того, что в нем позаботились о Generic параметрах, можно быть более спокойным о производительности.

Однако, чтобы уж совсем обезопаситься, логичнее делать так:

if (NLogLog.IsDebugEnabled)
{
    NLogLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}");
}

Здесь метод логгирования не будет вызываться, если это не надо. Однако, если всё-таки придется сбросить данные в лог, то тогда будет использован удобный String Interpolation. Внутри логгеры (по крайне мере тот же NLog) имеют оптимизацию, чтобы записывать строку в логи напрямую (т.е. форматирование будет происходить сразу в Stream, вместо создания строки в памяти). Однако эта оптимизация NLog'а меркнет с тем, что придется делать сброс данных в файл.

Пример из Kotlin

Чтобы разбавить описание работы популярных логгеров в .Net, приведу интересный способ оборачивания вызовов в kotlin. Идея строится буквально на одной интересной возможности языка: inline методы. Итак, простой код для вывода чего-то в debug:

class SomeService{
    private companion object : KLogging()

    fun publishData(id: Int){
        logger.debug {
            "Identity: $id"
        }        
    }
}

И он будет преобразован компилятором в подобие такого:

class SomeService{
    private companion object : KLogging()

    fun publishData(id: Int){
        if(logger.isDebugEnabled){
            try{
                val message = "Identity: $id"

                logger.debug(message)
            }catch (e: Exception){
                /*handle*/
            }
        }
    }
}

Здесь важно: всё, что внутри фигурных скобок возле debug — это лябмда. Однако она будет встроена в ваш метод, то есть в кучи не будет создан объект-функция. Таким образом, можно прятать большие операции внутри, которые будут вызван только если требуется сделать вывод результата в debug. Например:

class SomeService{
    private companion object : KLogging()

    fun publishData(id: Int){
        logger.debug {
            val idList = getIdList()

            "Identity: $idList"
        }
    }
}

Здесь getIdList будет вызван только если таки надо что-то отправить в файл. А всё потому, что код преобразуется в:

class SomeService{
    private companion object : KLogging()

    fun publishData(id: Int){
        if(logger.isDebugEnabled){
            try{
                val idList = getIdList()

                val message = "Identity: $idList"

                logger.debug(message)
            }catch (){
                /*handle*/
            }
        }
        logger.debug {
            "Identity: $id"
        }
    }
}

Large Object ==> Large Object Heap

В дополнении к предыдущему примеру. Я уверен, что многие знаю, что в .Net/JVM есть понятие "Large Object Heap". Точнее, в Java нет специального определения, однако аллокаторы зачастую будут создавать большие объекты сразу в последнем поколении (чтобы минимизировать перемещение объектов и нивелировать проблему быстрого пробития памяти для потокового аллокатора).

Вернемся к примеру:

NLogLog.Debug($"Id={id}");

Как Вы понимаете, если объект id имеет реализацию ToString, которая создает строку размером в мегабайт, то на лицо следующие попадания в LOH:

• Сам вызов ToString
• Форматирование $"Id={id}"
• А если разработчики логгера не отловили все подобные вещи (а крайне сложно написать тест на отсутствие объектов в LOH), то логгер еще добавит проблем.

И здесь можно пользоваться тремя способами логгирования подобных вещей:

• Использовать специальный layout и не требовать вызова ToString. Например, у NLog есть JsonLayout. Таким образом в логгер можно просто передать объект, который будет сериализован сразу в результирующий поток (например — в файл).
• Писать в файл самостоятельно. Или другими словами — не использовать логгер. От себя могу только посоветовать способ, как узнать, в какой файл будет писать NLog: var filePath = NLog.LogManager.Configuration.AllTargets.OfType<FileTarget>().First().FileName.Render(LogEventInfo.CreateNullEvent()). Очевидно, эта функция вернет первый попавшийся FileTarget, однако если все пишут в одну папку, то подобным способом можно узнать папку для записи, а потом напрямую отправить дамп вашего объекта в файл.
• Если у Вас log4j2 (именно второй, это важно), то можно использовать StringBuilderFormattable. Он как раз создан для того, чтобы вывести данные в логгер кусочками (более того — чтобы еще не выделять часть кусочков в куче, так как они уже выделены).

public interface StringBuilderFormattable {

    /**
     * Writes a text representation of this object into the specified {@code StringBuilder}, ideally without allocating
     * temporary objects.
     *
     * @param buffer the StringBuilder to write into
     */
    void formatTo(StringBuilder buffer);
}

Синхронность (и проблемы асинхронности)

Как-то раз в одной программе я заметил, что во время нагруженных операций порядка половины времени ожидания UI приходилось на операции логгирования. Еще раз: половина времени работы программы уходило на вызов logger.Debug или что-то в этом духе. А причина в этом проста: мы использовали log4net, который умеет писать файлы только синхронно.

Отсюда я вывел правило 1: логгер всегда должен работать в другом потоке. Вы не должны блокировать код приложения ради трейсов, ибо это невероятно странно. Другими словами — используя NLog — всегда необходимо проставлять async=true в теге nlog (он главный). Или, как сказано в примере:

<targets async="true"> 
  ... your targets go here ...
</targets>

Если Вы используете log4net — то или сделайте перенаправление с него на NLog, или же сделайте AsyncFileAppender.

Для Java мира: и Logback и Log4J2 имеют возможности делать асинхронное логгирование. Вот сравнение с официального сайта:

Однако когда у вас всё пишется асинхронно, то возникает другая проблема — а что делать в случае критических ошибок? Ведь бывает такое, что программа завершает работу не потому, что вышли из потока Main (например, программа может завершиться путем вызова Application.Exit или Environment.FailFast, что не очень красиво, однако встречается). В этом случае необходимо всегда вызывать Flush перед тем, как убить свой процесс. Иначе при падении на боевом сервере самая ценная информация будет упущена.

Вывод

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

В любом случае, как я уже говорил в начале, работа с логгерами есть практически каждом приложении. Более того, по моим заметкам, порядка половины классов сами выводят что-то в лог. Таким образом, правильная работа с этими функциями влияет практически на всё приложение целиком.