How fast the logger could be?

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

Задача взялась вполне себе из практики: есть приложение, которое зарабатывает бабло наносит пользу человечеству. У этого приложения есть legacy-версия, которая уж сколько-то лет в работе, и есть новая, с 0 переписанная (в основном мной) версия, которая сейчас готовится ее сменить на боевом посту. Разумеется, возникает масса вопросов вида "а почему вот в новой версии у этой транзакции результат чуть не такой, как в старой?". И приходится много времени шароебиться по логам, выясняя, как и что происходило. И, конечно, регулярно думаешь, что вот если бы еще здесь, здесь, и вот здесь дополнительно ключевые параметры сбрасывать в лог, то расследование было бы в разы быстрее и проще.

Казалось бы, в чем проблема-то? Проблема в том, что заказанное среднее время обработки транзакции в приложении <100us (мы пока до него не дотягиваем, но стараемся). В этих условиях приходится быть довольно экономным. Примерная стоимость вызова log4j.info() в асинхронном режиме где-то 5мкс — особо не разбежишься. Новая версия приложения давно уже использует gflogger как основной инструмент для логгирования, но даже здесь стоимость вызова примерно 1мкс, что, конечно, гораздо лучше, но все-таки еще многовато. Хочется же уместить 30-100 вызовов логгера в <10us (т.е. <10% целевого времени ответа). Другими словами, мне нужно решение для логгирования, которое требует 100-300нс/запись. Так вот, вопрос — можно ли так сделать?

В принципе, примерный маршрут виден: многие вещи уже обкатаны Володей при разработке gflogger-а. Garbage-free API, GC-free реализация с преаллоцированными буферами — все это себя вполне хорошо зарекомендовало. Но gflogger все-таки делался по принципу "возьмем log4j, отрежем весь явно лишний функционал, а так же еще что под руку попадется, и реализуем остальное". Большое преимущество такого подхода "сверху вниз" — короткий путь "до рынка": тот же gflogger начали использовать уже через пару месяцев после начала его разработки. Недостаток же в том, что в большой системе с обширным функционалом довольно сложно понять, кто какой вклад в производительность вносит. Просто-напросто слишком много вариантов того, что можно убрать/добавить/сделать иначе. Поэтому лично я предпочитаю вести ОКР в обратном направлении, снизу вверх — от примитивов, шаг за шагом собирая нужный мне комплект функционала, с постоянным бенчмаркингом. Чудеса случаются и здесь, но в целом, мне кажется, такой маршрут дает гораздо более понятную картину.

Собственно, так я здесь и сделал: поставил себе задачу собрать асинхронный логгер с gflogger-like API, на базе кольцевого буфера, с записью в один-единственный файл. Вообще-то, до записи как раз руки и не дошли, потому что меня больше интересовала не пропускная способность (по всем прикидкам она более чем достаточна для моих целей), а накладные расходы рабочих потоков, т.е. время вызова log.message(...).

Что получилось: удалось добиться ~150ns/message в 4-х поточном случае.

Что использовал и на какие компромиссы пришлось пойти:

• Multi-threaded claiming: я рассказывал про это еще полтора года назад на jug-е: можно сильно улучшить масштабирование, и, что еще важнее, уменьшить простои потоков (т.е. приблизить к wait-free) если вместо общего на всех курсора publishedSequence использовать флаг в каждой конкретной записи.
• Только примитивные аргументы. Во-первых это в целом упростило API. Во-вторых с примитивными аргументами можно заранее вычислить нужный размер записи. Без этого пришлось бы либо выделять по-максимуму, с запасом, либо сначала писать все во временный буфер, а потом копировать в основной.
• Компактное представление записи: я не форматирую сообщение прямо в рабочем потоке, я пишу в буфер непосредственно messageId+arguments Во-первых, это гораздо компактнее, чем готовое сообщение (чаще всего, но не всегда — нашел у себя в проекте пару изощренных контрпримеров), а размер сообщения сильно влияет на время записи. А во-вторых, снимает с рабочих потоков задачу форматирования. Разумеется, это так легко и эффективно получилось только вкупе с предыдущим пунктом — если добавлять кроме примитивов хотя бы даже строки, подозреваю, эффективность заметно упадет.
• Вариабельный размер записи. Это интересная тема, про которую меня регулярно спрашивали в контексте дизраптора и кольцевых буферов вообще. На пальцах казалось, что ничего принципиально сложного нет, но случая проверить до сих пор не выпадало. На первый взгляд непонятно, зачем это здесь, но я прицеливался в то, чтобы на каком-то этапе в будущем можно было использовать в качестве буфера memory-mapped file, и тогда оставлять много пустых мест кажется плохой идеей. Исходя из этой задумки я и решил, что вот он мой шанс наконец-то попробовать. Реализовывать эту штуку было очень интересно, но возникает много тонкостей. В целом мой вывод: для себя интересно, но если нет реальной необходимости, на работе лучше не заморачиваться и использовать записи фиксированного размера, гораздо проще выходит

На чем в основном тратим время? Вполне предсказуемо: где-то 2/3 времени примерно поровну делят между собой addAndGet на выделении записи и собственно запись данных в буфер. Остальная треть приходится на все остальное, типа thread local-ов и прочих накладных расходов. В принципе, у меня есть идея как несколько ускорить выделение записей, но надо еще думать.

Проект лежит здесь вместе со всеми бенчмарками. На всякий случай еще раз уточняю: это не рабочий код, и даже не альфа-версия, это экспериментальный код с бенчмарками. В лучшем случае тянет на прототип.