Содержание

четверг, 31 марта 2011 г.

Получение абсолютного времени в GC логах

Зачем это вообще нужно спросите вы? Объясняю. Если в вашем приложении есть операции чувствительные к времени выполнению, то вы наверное замечали, что иногда эти операции неожиданно выполняются заметно большее время, нежели в среднем. Такое эффект может быть объяснен срабатыванием GC. Наиболее это заметно, когда происходит Full GC. Однако, проблема в том, что стандартный JVM логгер, не пишет абсолютное время, а печатает количество секунда от старта java машины и заматчить это время с абсолютным временем, которое пишется в обычные логи очень проблематично.

Начнем, с самого начала. Чтобы включить GC логи с таймстемпами, необходимо запустить JVM с параметрами:
Допустим, вы получили следующий лог:
Как мы видим, секунды печатаемые в логах на мало о чем говорят, и было бы намного приятнее, если мы бы видели абсолютное время. Для начала, надо определить момент от начала UNIX эпохи в миллисекундах, когда ваша java машина запустилась. Это можно сделать с помощью JMX (http://java.sun.com/j2se/1.5.0/docs/api/java/lang/management/RuntimeMXBean.html):
Допустим, это выражение вернуло число 1301551324913. Осталось только запустить парсер:
Если у вас логи уже зазипованы, то можно и так:
В итоге получаем:
Несколько комментариев:
1. Время, к сожалению, удалось сделать только в локальной временной зоне.
2. Если JVM уже закончила, свою работу, то по JMX к ней не подключиться. Откуда же взять время? Самое простое, логировать его на старте JVM. Проблема в том, что UNIX не хранит время создания файла в атрибутах, поэтому его вытащить не так просто. Конечно можно поднапрячься и брать в атрибутах файла last-modified, читать таймстемп в последней строчки файла и вычислять на основе этого. Но это упражнение требует определенных упражнений.

Исходники скрипта: