Logging Gotcha

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

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

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

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

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

view raw logging.java hosted with ❤ by GitHub

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

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

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

view raw logging.java hosted with ❤ by GitHub

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

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

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

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

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

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

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

view raw oldstyle.java hosted with ❤ by GitHub

писать

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

view raw newstyle.java hosted with ❤ by GitHub