gflogger 0.0.9.x

Garbage Free Logger добрался до версии 0.0.9.x .

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

Но обо всём по порядку.

Но всё же, стоит, пожалуй, начать рассказом о специфике нашего приложения: по сути это обработка потока, очень чувствительное к задержкам, работающее на куче в 1Gb - больше нам не надо, подтвеждено тестами и лучшими стоматологами. Впрочем те же тесты под хорошей нагрузкой (выше среднего) показали, что full gc collection у нас не случается, а длительность суммарного minor gc collection не выше 20 мс.

Как это почти всегда водится, идея gflogger'а возникла утром на работе за чашечкой кофе - Евгений Т. предложил использовать off heap память ( волшебный камень no. 1 ) для logging'а, поскольку наше ключевое приложение пишет немало логов и существовало понимание того, что неявно, через сборщик мусора, это влияет на приложение. Т.о. хотелось получить garbage less логгер.

Сказано - сделано: вечером того же дня был написан прототип. Параллельно возникла идея сделать не garbage less, а garbage free т.е с волшебным свойством Zero Object Delivery.

Дабы быть честным, отмечу, что если быть педантом, то нельзя сказать, что это garbage free в полном смысле этого слова т.к. есть фаза запуска, когда мусор некоторый создаётся. Однако в стационарной фазе, без нарушения контракта использования (об ограничениях чуть позже), он действительно garbage free, что более чем применимо в условиях нашего приложения.

Уточнение от Peter Lawrey: лучше говорить, не что мы не создаём объектов, а что мы их не выбрасываем. Т.е создаём объекты, но переиспользуем их неоднократно.

К этому моменту уже случился disruptor hype, так, что disruptor как нельзя лучше подошёл и стал компонентом no. 2.

Как только появился прототип встала проблема тестирования как уровня мусора, производительности (в сравнении с конкурентами типа log4j и logback), так доказательство того, что это действительно garbage free.

Другой герой, притаившийся за кулисами, no. 0: java-allocation-instrumenter - java агент отслеживающий точки создания новых объектов - является очень важным для всего gflogger, хотя дальше чем тесты и benchmark'и он не выходит.

Пример использования gflogger:

log.info().
    append("property named '").
    append(name).
    append("' has value ").
    append(value).
  commit();

Много было идей как называть методы: были идеи использовать a(...) как append(), а z() как commit(), обыгрывая идею «от начала и до конца» (a-z). Предлагался и православный вариант с amen() вместо commit(), но всё же осталось то, что осталось.

Изначально в дизайн логгера было заложено множество вполне разумных ограничений, таких, например, как ограниченная максимальная длина сообщения. Это связано прежде всего с тем, что память резервируется заранее. Также предполагалось, что данный логгер будет использоваться бок о бок с другими логгерами (log4j), которые будут использоваться в менее latency критических блоках. Т.е. с самого начала предполагалось, что это не будет ни в коем случае никакой не убийца log4j, logback или что вы там ещё любите, а вполне себе такой ad hoc для чувствительных к latency местах.

Ни о каком удобстве конфигурации через xml файлы, не тем более о иерархии категорий.

Казалось бы вон оно счастье, близко за не укусишь. Душа просит цифр и фактов. Первый же benchmark, написанный по всем законам жанра - с прогревом как у реактивного самолёта, всё как положено и ... осечка - почти линейная зависимость по времени работы gc от количества сообщений.

Что-то явно где-то подтекает.

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

Но вернёмся же к нашим баран шаблонам: мы обычно используем, кроме самого сообщения ещё и метку времени, имя категории (класса или его части), а так же имя нити из которой было отправлено сообщение.

Моему удивлению не было предела: «мусорил» метод thread.getName(). Впрочем, автор java.lang.Thread в jdk пожелал остаться неизвестным (unascribed), канул в лета за давностью лет.

Первые версии, которые, однако, никак не помечались в репозитории ( просто публиковались в локальный ivy репозиторий ), страдали многими детскими болезнями, такими как переинициализация, и моя коллега Юля В., ныне работающая в g**g*e, стала первой кто начал обкатывать gflogger. Так оно жило до версии 0.0.6 .


В апреле случился Moscow Oracle Developer Day он же бывший Java One Days, на котором делал доклад о gflogger.

За день до Moscow Oracle Developer Day случилось то, что должно было случиться : репозиторий был переведён из приватного в публичный, а версия 0.0.6 первая публичная версия под Apache license.

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

Так почему же это open source ?

Прежде всего это моя любовь к open source движению в целом. Во вторых все используемые базовые компоненты или честно экспроприированный код - это тоже open source открытые под apache license.

Но это всё то, что лежит на поверхности и слишком очевидно. Другая сторона заключена в том, что это своего рода реклама работодателя.
Первый же вопрос, который мне задали на Moscow Oracle Developer Day звучал примерно так: «Чем вы занимаетесь, что для Вас суммарный stop-the-world в 30 ms это время ?». А ещё, а у нас, а мы, а я мы занимаемся много чем другим полезным и интересным.


Но всё же, вернёмся с фенечкам, бортикам и прочим рюшечкам.

Ещё одной, немного запоздалой идеей стало использование однобайтового представления символа (char): как известно, в java представление char базируется на стандарте unicode, и поэтому занимает 2 байта.
Начиная с java6u21 можно использовать флаг -XX:+UseCompressedStrings, это позволяет java.lang.String использовать массив байт вместо массива символов (char).

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

Дальше - больше. Harald W., решает использовать gflogger в проекте, который только только должен пойти в live. И что самое удивительное как general purpose logger.

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

Где бы я ещё мог увидеть начальника так лихо линчующего гокод ? Между делом Harald W. влил в кодовую базу настройщик из xml файла.

Дмитрий Г. не раз натыкался на краевые моменты - забыл закоммитить сообщение, но не понятно откуда это произошло. Или форматирование исключений немного не православное и среда разработки не помогает автоматично перескочить на нужную строчку кода. Словом даёшь валидацию и человеческое морлицо.

Руслан, надкусывая шоколадку и в очередной раз радуясь google guava, захотел ещё больше сладкого - и теперь можно использовать шаблоны форматирования в сообщении. Словом, как-то так:

log.info("property named '%s' has value %s").
    with(name).
    withLast(value);

Ещё одной хорошей идеей от Руслана стали форматировщики объектов: раньше, если добавить через append() некоторый объект, то он по факту, будет добавлен через метод toString(), что приводит к мусору. В то же время, завязывать свои доменные объекты на gflogger через интерфейс Loggable можно, но не хочется. Регистрируя ObjectFormatter можно задавать отображение некоторого класса в gflogger представление.

И в заключение - мои коллеги по команде в том или ином виде вносят вклад в дело gflogger: кто отличными идеями, кто практической обкаткой кода и замечаниями по улучшению, кто-то внесением правок в кодовую базу, ломая тем самым исходные ограничения, но оставаясь garbage free.

Тем временем на подходе версия 0.1.0, с шахматами, поэтессами, и всём тем, что уже есть в 0.0.9.* .