Tail Spin

Blog So Hard

Logging Gotcha (Rus)

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

Современные библиотеки позволяют сохранять информацию на различных уровнях логгирования. В проектах, в которых я участвовал, обычно используется четыре уровня логгирования:

  • ERROR – сюда выводится информация о критичных ошибках в системе.
  • WARN – используется для вывода не критичных, но все же некорректных сиптомов неправльной работы приложения
  • INFO – используется для вывода интересных событий происходлящих в системе
  • DEBUG – детальныая информация о том, что происходит с системой. обычно используется при разработке либо при отладке.

Обычно запись в лог выглядит довольно просто:

1
2
3
4
log.error("SOMETHING REALLY BAD HAPPENED")
log.warn("Something bad happened")
log.info("Startup")
log.debug("Processing request" + request)

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

До сих пор, строки кода в open source библиотеках вида:

1
2
3
if (log.isDebugEnabled()) {
    log.debug("Processing request" + request);
}

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

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

Очень часто во время вывода в debug строки конкатенируются. И конкатенируются они независимо от того влючен дебаг или нет. Это во-первых приводит к тому, что создаются лишние строки что приводит к большим вызовам GC.

Во-вторых, операция toString может занимать продолжительное количество времени, и как показала недавняя история до 15% времени тормозящего метода.

Получается писать проверку влюченности уровня необходимо. Но не удобно. Количество строчек кода для записи в лог увеличивается в три раза.

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

Вместо конкатенации строк при логировании

1
log.debug("Processed request " + request + " sending response " + response);

писать

1
log.debug("Processed request {} sending response {}", request, response);