Blog Relocated

Oops, Блог переехал. http://mairbek.github.com/blog.html

Logging Gotcha

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

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

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

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

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

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


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

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

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

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

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

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

писать

Microbenchmarking with Caliper

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

Чаще всего, конечно, можно воспользоваться гуглом, задать вопрос на stackoverflow, но в некоторых ситуациях ничего не остается, кроме как провести эксперименты самому.

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

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

Зная что нужно измерять, написать бенчмарк довольно тривиально, и, часто, вполне можно обойтись одним единственным статическим методом main. Однако, используя фреймверк Caliper от компании Google, бенчмарки можно писать быстро и с удовольствием, выкинув при этом кучу boilerplate кода.

API Caliper в чем то напоминает старую версию JUnit. Для того чтобы написать простой бенчмарк нужно:

1. Отнаследоваться от класса com.google.caliper.SimpleBenchmark.
2. Написать тестовые методы, название которых начинается со слова time.
3. Подготовка данных и очистка ресурсов происходит в методах setUp и tearDown соответственно.

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

Запустив тест мы убедимся, что разницы в производительности нет.

Еще один пример. Допустим, мы разрабатываем функциональность которая предполагает огромное количество операций над дробными числами, и мы думаем стоит ли использовать BigDecimal или лучше остановить свой выбор на старом добром быстром double. Сравнить насколько медленней будет работать BigDecimal для такой операции как умножение не сложно.

Прогнав тест, становится видно, что для небольших чисел и чисел с небольшой дробной частью BigDecimal работает в 5 раз медленней, а для больших чисел либо чисел с большим количеством символов после запятой в 20 раз.

Следует заметить, что JVM хитрая штука, и постоянно занимается оптимизацией кода, что сказывается на результатах бенчмарка, по-этому иногда надо выкручиваться. Например, в бенчмарке DoubleVsBigDecimalBenchmark используется массив и странный способ инициализации переменной v нулем.