4 февраля 2014 г.

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-ов и прочих накладных расходов. В принципе, у меня есть идея как несколько ускорить выделение записей, но надо еще думать.

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

22 комментария:

  1. Один из подводных камней на которых наткнулся - это именно IO - частый flush на диск приводит к общему проседанию, слишком редкий тоже не очень.

    Интересно какие накладные расходы дает IO - и наверняка это в зависимости от размера буфера/данных, которые пишутся.

    ОтветитьУдалить
    Ответы
    1. Не очень понятно, как может вообще работа разгребатора что-то тормозить, если общая пропускная способность IO выше, чем требуется? Казалось бы, пока ты там что-то пишешь на диск -- рабочие потоки что-то пишут в буфер, никто им не мешает.

      Удалить
    2. Как минимум то, что нагребатор успевает накидать больше, чем может разгребатор записать ни диск.

      Удалить
    3. Ты где столько данных-то берешь? Ну и если их правда столько, то тут уже некуда деваться. Либо диски лучше ставить, либо в сеть сбрасывать, если карточка хорошая

      Удалить
    4. Запишешь ли ты 1кб или 1мб для диска почти одно и то же - поэтому разгребатор почти всегда копит буфер на запись и при достижении некоторого объема (или таймаута) скидывает на диск.

      Удалить
  2. Вспоминается фраза Романа Елизарова на одном из его докладов - "Как решаются проблемы с логгированием ? Правильно, не логгировать". )))
    Это ради хохмы.

    Как было решено флушить логи ?

    ОтветитьУдалить
    Ответы
    1. Я вообще не планировал явно сбрасывать. Пишу в FileChannel, а там пусть реализация разбирается, сколько у нее буфер. Для mmap файлов это тоже не актуально.

      Удалить
  3. Любопытно.

    Если не задумываться, то первое, что приходит на ум.
    Логгировать в MappedByteBuffer. Если Linux, то /dev/shm (на диск не пишется ничего).
    Потом его с помощью RDMA передавать на другой хост, где можно писать куда угодно.

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

    RDMA - не важно что конкретно InfiniBand, iWARP или RoCE.

    Если вопрос цены важен, то старые InfiniBand 10G стоят до 50$.

    ОтветитьУдалить
    Ответы
    1. И
      > Вариабельный размер записи

      У меня есть такая либа. Примитивная, но хорошая :-).
      Один процесс в сериализованном виде пишет объекты в MappedByteBuffer.
      Другой читает оттуда. Конечно кольцевой буфер. Блокровок нет, ибо CAS из знаменитого misc.unsafe. Если нужна ОЧЕНЬ высокая пропускная способность (мне это не надо), то размер буфер можно оттюнить для cache-friendly и тогда более 200 млн. int-ов в секунду можно получить.
      Размер записи произвольный.
      Если буфер переполнен, то писатель паркуется на несколько наносекунд.

      Только вот для логгера переполнение кольцевого буфера очень плохо.

      Удалить
    2. И забыл ;-). P.S.

      > Проблема в том, что заказанное среднее время обработки транзакции в приложении <100us

      Возможно придётся писать свои очереди т.д.

      Например, моё либу можно использовать внутри одного процесса - пропускная способность одинаковая.
      Стандартные очереди с одним издателем и одним подписчиком у меня МАКСИМУМ 11 млн. int-ов в секунду.

      Удалить
    3. Да, именно такой и видится конечная штуковина. Насчет второго процесса я не уверен, что он мне нужен -- пусть прямо логи лежат и все.

      Удалить
    4. Я бы ещё , наверное, AOP заюзал, но это дело вкуса.
      Всякие AOP-фреймворки используют манипуляции с байткодом для внедрения аспектов. Не каждый человек нормально к этому относится ;-).


      Ещё можно JSR 269 заюзать. Создаём нужные аннотации. Можно даже для локальных переменных, которые в скомпилированном коде вообще не видны. Потом реализуем процессор аннотаций, который может использовать Compiler Tree API (спецификации, правда, на него нет). Конкретные классы, которые реализуют это API известны. Благодаря этому мы спокойно модифицируем абстрактные синтаксические деревья во время компиляции.

      Итого. Ставим на нужном методе (или локальной переменной) аннотацию, а во время компиляции в нужное место автоматически вставляется вызов логгера! И появляется возможность не вставлять данные вызовы, когда это не надо. Условная компиляция в Java !!
      На первый взгляд может показать грязным хаком, но это намного чище, чем инструментация байткода. Основной недостаток - работает только с OpenJDK/Oracle JDK.


      Удалить
    5. > Если буфер переполнен, то писатель паркуется на несколько наносекунд.

      В смысле, спинлупится несколько наносекунд? И несколько -- это сколько?

      Удалить
    6. Какое это имеет значение сколько конкретно у меня :-) ?
      Когда измерял пропускную способность, то было 5. Сейчас 500 обычно использую, но у меня относительно мало живых данных.
      LockSupport.parkNanos, который использует sun.misc.Unsafe .

      Если имеет значение производительность, то вот советы:
      http://psy-lob-saw.blogspot.ru/2013/03/single-producerconsumer-lock-free-queue.html
      Вообще весь блог экстра охренительный.
      Вот проект блога https://github.com/nitsanw/JAQ-InABox
      Некоторые очереди из него более 300 млн. int-ов в секунду.

      Удалить
  4. ETW через JNI не рассматривали в качестве альтернативы?

    ОтветитьУдалить
    Ответы
    1. Event Tracing for Windows (http://tinyurl.com/k35fk7u). Пример либы: http://sergeim.codeplex.com/
      Конечно, Windows-only, но вряд ли получится сделать локальное логгирование быстрее, чем ETW.

      Удалить
    2. Event Tracing for Windows (ETW) is an efficient kernel-level tracing facility.

      Все low latency системы придерживаются правила "Avoid the kernel" (в общем случае даже TCP не подходит). TCP ещё можно оставить, но лезть самому лишний раз в ядро не стоит.

      P.S.
      А вообще JNI не самая удачная штука в Java :-) . И можно даже обойтись без написания обёртки BridJ или JNA. Можно JNAerator попробовать, который их использует и генерит java-интерфейсы.

      Удалить
    3. Using a buffering and logging mechanism implemented in the kernel, ETW provides a tracing mechanism for events raised by both user-mode applications and kernel-mode device drivers.
      Вопрос в том, будут ли вызываться функции ядра для логгирования user-mode событий. Нет, если ETW сессия создаётся для in-proc ивентов.
      ntdll!EtwLogTraceEvent в этом случае использует ntdll!EtwpTraceUmEvent (который использует shared memory) вместо ntdll!NtTraceEvent.
      Просто не вижу смысла писать велосипед, когда быстрое логгирование простых типов предоставляется средствами ОС. И я упомянул ETW в качестве платформенно-зависимой альтернативы, если остальные подходы не оправдали ожиданий.

      Спасибо, не знал про JNAerator, нужно будет попробовать на досуге.

      Удалить
  5. Если не секрет, за счет чего достигается GC-Free ?

    ОтветитьУдалить
    Ответы
    1. Garbage-free -- за счет того, что по ходу работы ничего не аллоцируется. Все, что нужно -- создано однажды, на стартапе.

      Удалить