JEP 158: Unified JVM Logging

Аннотация

Ввести общую систему журналирования для всех компонентов JVM.

Цели

• Общие параметры командной строки для всего журналирования
• Сообщения журнала классифицируются с помощью тегов (например, compiler, gc, classload, metaspace, svc, jfr, ...). У одного сообщения может быть несколько тегов (набор тегов)
• Журналирование выполняется на разных уровнях: error, warning, info, debug, trace, develop.
• Можно выбирать, какие сообщения записываются в журнал, в зависимости от уровня.
• Можно перенаправлять журнал в консоль или в файл.
• Конфигурация по умолчанию: все сообщения уровней warning и error выводятся в stderr.
• Ротация файлов журнала по размеру и по числу хранимых файлов (аналогично тому, что сейчас доступно для журналов GC)
• Вывод построчно (без перемешивания внутри одной строки)
• Сообщения журнала записываются в виде человекочитаемого простого текста
• Сообщения могут быть «декорированы». Декорации по умолчанию: uptime, level, tags.
• Возможность настраивать, какие декорации будут выводиться.
• Существующее журналирование «tty->print...» должно использовать единое журналирование для вывода
• Журналирование можно настраивать динамически во время выполнения через jcmd или MBeans
• Протестировано и поддерживается — не должно приводить к аварийному завершению, если пользователь или клиент его включит

Дополнительные цели:

• Многострочное журналирование: несколько строк можно записать так, чтобы при выводе они оставались вместе (не перемешивались)
• Включение и отключение отдельных сообщений журнала (например, с помощью __FILE__ / __LINE__)
• Реализовать вывод в syslog и в Windows Event Viewer
• Возможность настраивать, в каком порядке должны выводиться декорации

Что не является целью

Добавление самих вызовов журналирования во все компоненты JVM выходит за рамки этого JEP. Этот JEP предоставит только инфраструктуру для журналирования.

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

Этот JEP не добавляет журналирование в код на Java в JDK.

Мотивация

JVM — сложный системный компонент, и анализ первопричин проблем в нём часто оказывается трудной и долгой задачей. Без развитых средств обслуживания найти первопричину периодических аварийных завершений или странностей производительности в рабочей среде часто почти невозможно. Детальное и легко настраиваемое журналирование JVM, которым могут пользоваться инженеры поддержки и сопровождения, — одно из таких средств.

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

Описание

Теги

Фреймворк журналирования определяет в JVM набор тегов. Каждый тег идентифицируется своим именем (например: gc, compiler, threads и т. д.). Набор тегов можно при необходимости изменять в исходном коде. При добавлении сообщения журнала его следует связать с набором тегов, который классифицирует записываемую информацию. Набор тегов состоит из одного или нескольких тегов.

Уровни

С каждым сообщением журнала связан уровень журналирования. Доступные уровни в порядке возрастания подробности: error, warning, info, debug, trace и develop. Уровень develop доступен только в непродуктовых сборках.

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

Декорации

Сообщения журнала декорируются сведениями о сообщении. Вот список возможных декораций:

• time — текущие время и дата в формате ISO-8601
• uptime — время с момента запуска JVM в секундах и миллисекундах (например, 6.567s)
• timemillis — то же значение, что возвращает System.currentTimeMillis()
• uptimemillis — миллисекунды с момента запуска JVM
• timenanos — то же значение, что возвращает System.nanoTime()
• uptimenanos — наносекунды с момента запуска JVM
• pid — идентификатор процесса
• tid — идентификатор потока
• level — уровень, связанный с сообщением журнала
• tags — набор тегов, связанный с сообщением журнала

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

Пример: [6.567s][info][gc,old] Old collection complete

Вывод

Сейчас поддерживаются три типа вывода:

• stdout — вывод в stdout.

• stderr — вывод в stderr.

• text file — вывод в текстовые файлы.

  Можно настроить ротацию файлов по записанному объёму и числу файлов в ротации. Пример: ротировать файл журнала каждые 10 МБ, хранить в ротации 5 файлов. К именам файлов добавляется их номер в ротации. Пример: hotspot.log.1, hotspot.log.2, ..., hotspot.log.5 К имени текущего открытого файла номер не добавляется. Пример: hotspot.log. Размер файлов не обязательно в точности совпадает с заданным. Он может превышать заданный не более чем на размер последнего записанного сообщения журнала.

Для некоторых типов вывода может потребоваться дополнительная настройка. Дополнительные типы вывода можно легко реализовать через простой и чётко определённый интерфейс.

Параметры командной строки

Будет добавлен новый параметр командной строки для управления журналированием всех компонентов JVM.

• -Xlog

Несколько аргументов применяются в том порядке, в котором они указаны в командной строке. Несколько аргументов «-Xlog» для одного и того же вывода переопределяют друг друга в заданном порядке. Действует последняя конфигурация.

Для настройки журналирования используется следующий синтаксис:

-Xlog[:option]
    option         :=  [<what>][:[<output>][:[<decorators>][:<output-options>]]]
                       'help'
                       'disable'
    what           :=  <selector>[,...]
    selector       :=  <tag-set>[*][=<level>]
    tag-set        :=  <tag>[+...]
                       'all'
    tag            :=  name of tag
    level          :=  trace
                       debug
                       info
                       warning
                       error
    output         :=  'stderr'
                       'stdout'
                       [file=]<filename>
    decorators     :=  <decorator>[,...]
                       'none'
    decorator      :=  time
                       uptime
                       timemillis
                       uptimemillis
                       timenanos
                       uptimenanos
                       pid
                       tid
                       level
                       tags
    output-options :=  <output_option>[,...]
    output-option  :=  filecount=<file count>
                       filesize=<file size>
                       parameter=value

Тег «all» — метатег, включающий все доступные наборы тегов. «*» в определении «tag-set» обозначает сопоставление тегов по шаблону («wildcard»). Отсутствие «*» означает «все сообщения, теги которых в точности совпадают с указанными».

Если «what» полностью опущено, по умолчанию используются набор тегов all и уровень info .

Если «level» опущено, по умолчанию используется info

Если «output» опущено, по умолчанию используется stdout

Если «decorators» опущено, по умолчанию используется uptime, level, tags

Декоратор «none» особый и служит для отключения всех декораций.

Указанные уровни включают в себя менее подробные. Например, если для вывода задан «level» info. Будут выводиться все сообщения, соответствующие тегам из «what», с уровнями журналирования info, warning и error.

-Xlog:disable
    this turns off all logging and clears all configuration of the
    logging framework. Even warnings and errors.

-Xlog:help
    prints -Xlog usage syntax and available tags, levels, decorators
    along with some example command lines.

Конфигурация по умолчанию:

-Xlog:all=warning:stderr:uptime,level,tags
    - default configuration if nothing is configured on command line
    - 'all' is a special tag name aliasing all existing tags
    - this configuration will log all messages with a level that
    matches ´warning´ or ´error´ regardless of what tags the
    message is associated with

Простые примеры:

-Xlog

равносильно

-Xlog:all
    - log messages using 'info' level to stdout
    - level 'info' and output 'stdout' are default if nothing else
    is provided
    - default output of all messages at level 'warning' to 'stderr'
    will still be in effect

-Xlog:gc
    - log messages tagged with 'gc' tag using 'info' level to
    'stdout'
    - default output of all messages at level 'warning' to 'stderr'
    will still be in effect

-Xlog:gc=debug:file=gc.txt:none
    - log messages tagged with 'gc' tag using 'debug' level to
    a file called 'gc.txt' with no decorations
    - default output of all messages at level 'warning' to 'stderr'
    will still be in effect

-Xlog:gc=trace:file=gctrace.txt:uptimemillis,pid:filecount=5,filesize=1M
    - log messages tagged with 'gc' tag using 'trace' level to
    a rotating fileset with 5 files with size 1MB with base name
    'gctrace.txt' and use decorations 'uptimemillis' and 'pid'
    - default output of all messages at level 'warning' to 'stderr'
    will still be in effect

-Xlog:gc::uptime,tid
    - log messages tagged with 'gc' tag using default 'info' level to
    default output 'stdout' and use decorations 'uptime' and 'tid'
    - default output of all messages at level 'warning' to 'stderr'
    will still be in effect

-Xlog:gc*=info,rt*=off
    - log messages tagged with at least 'gc' using 'info' level but turn
    off logging of messages tagged with 'rt'
    - messages tagged with both 'gc' and 'rt' will not be logged
    - default output of all messages at level 'warning' to 'stderr'
    will still be in effect

-Xlog:disable -Xlog:rt=trace:rttrace.txt
    - turn off 'all' logging, even warnings and errors, except
    messages tagged with 'rt' using 'trace' level
    - output to a file called 'rttrace.txt'

Сложные примеры:

-Xlog:gc+rt*=debug
    - log messages tagged with at least 'gc' and 'rt' tag using 'debug'
    level to 'stdout'
    - default output of all messages at level 'warning' to 'stderr'
    will still be in effect

-Xlog:gc+meta*=trace,rt*=off:file=gcmetatrace.txt
    - log messages tagged with at least 'gc' and 'meta' tag using 'trace'
    level to file 'metatrace.txt' but turn off all messages tagged
    with 'rt'
    - again, messages tagged with 'gc', 'meta' and 'rt' will not be logged
    since 'rt' is set to off
    - default output of all messages at level 'warning' to 'stderr'
    will still be in effect

-Xlog:gc+meta=trace
    - log messages tagged with exactly 'gc' and 'meta' tag using 'trace'
    level to 'stdout'
    - default output of all messages at level 'warning' to 'stderr'
    will still be in effect

-Xlog:gc+rt+compiler*=debug,meta*=warning,svc*=off
    - log messages tagged with at least 'gc' and 'rt' and 'compiler' tag
    using 'trace' level to 'stdout' but only log messages tagged
    with 'meta' with level 'warning' or 'error' and turn off all
    messages tagged with 'svc'
    - default output of all messages at level 'warning' to 'stderr'
    will still be in effect

Управление во время выполнения

Журналированием можно управлять во время выполнения с помощью Diagnostic Commands (утилита jcmd). Всё, что можно задать в командной строке, можно задать и динамически с помощью Diagnostic Commands. Поскольку диагностические команды автоматически доступны как MBeans, изменять конфигурацию журналирования во время выполнения можно будет через JMX.

В список команд управления во время выполнения будет добавлена поддержка перечисления настроек и параметров журналирования.

Интерфейс JVM

В JVM будет создан набор макросов с API, похожим на следующий:

log_<level>(Tag1[,...])(fmtstr, ...)
    syntax for the log macro

Пример:

log_info(gc, rt, classloading)("Loaded %d objects.", object_count)
    the macro is checking the log level to avoid uneccessary
    calls and allocations.

log_debug(svc, debugger)("Debugger interface listening at port %d.", port_number)

Информация об уровне:

LogHandle(gc, meta, classunloading) log;
if (log.is_trace()) {
    ...
}

if (log.is_debug()) {
    ...
}

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

Производительность

Для разных уровней журналирования должны быть рекомендации, определяющие ожидаемые накладные расходы на производительность для каждого уровня. Например: «уровень warning не должен влиять на производительность; уровень info должен быть приемлемым для эксплуатации; к уровням debug, trace и error требований по производительности нет». Работа с отключённым журналированием должна как можно меньше влиять на производительность. Впрочем, журналирование всегда будет чего-то стоить.

Возможные расширения в будущем

В будущем может иметь смысл добавить Java API для записи сообщений журнала в эту инфраструктуру, чтобы им пользовались классы JDK.

Сначала будут разработаны только три бэкенда: stdout, stderr и файл. В будущих проектах могут быть добавлены другие бэкенды. Например: syslog, Windows Event Viewer, сокет и т. д.

Открытые вопросы

• Нужно ли предусмотреть в API альтернативу, при которой уровень передаётся макросу как параметр?
• Нужно ли обрамлять декорации чем-то другим, а не [], чтобы упростить разбор вывода?
• Каков точный формат декораций с датой и временем? Предлагается ISO 8601.

Тестирование

Крайне важно, чтобы само журналирование не вызывало никакой нестабильности, поэтому требуется обширное тестирование.

Функциональное тестирование придётся проводить, включая определённые сообщения журнала и проверяя их наличие в stderr или в файлах.

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

Инфраструктура журналирования будет протестирована с помощью модульных тестов.

Риски и допущения

Описанный выше дизайн может не охватывать все сегодняшние сценарии использования журналирования в JVM. В таком случае дизайн придётся пересмотреть.

Влияние

• Совместимость: изменятся форматы сообщений журнала и, возможно, смысл некоторых параметров JVM.
• Безопасность: необходимо проверить права доступа к файлам.
• Производительность и масштабируемость: если включён большой объём журналирования, это скажется на производительности.
• Удобство для пользователя: изменятся параметры командной строки. Изменится вывод журналирования.
• I18n/L10n: сообщения журнала не будут локализованы или интернационализированы.
• Документация: новые параметры и их использование придётся задокументировать.