Logging Gotcha

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

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

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

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

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

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


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

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

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

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

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

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

писать