Почему временные метки моего файла журнала Log4j вышли из строя, и как я могу это исправить?

Question

My log4j.xml содержит:

<appender class="org.jboss.logging.appender.RollingFileAppender" name="rm">
  ...
  </layout>

Мой файл журнала показывает временные метки, которые не в порядке. Можем ли мы отобразить на основе отметки времени?

2009-02-19 14:47:01,288 DEBUG [com.catalystwms.core.persistence.TransactionContext]  
2009-02-19 14:54:27,429 INFO [com.catalystwms.tms.services.background.purge.PurgeManager]  
2009-02-19 14:47:01,288 DEBUG [com.catalystwms.core.services.ServiceLocator] 

Пожалуйста, помогите мне.

Спасибо

Answer 1

Два оператора журнала, встречающиеся в разных потоках.

(Тема 1) 2009-02-19 14: 54: 27,429 ИНФОРМАЦИЯ [com.catalystwms.tms.services.background.purge.PurgeManager]
(Тема 2) 2009-02-19 14: 47: 01,288 DEBUG [com.catalystwms.core.services.ServiceLocator

Я полагаю, что время записи в журнале точно указывает время, когда произошло событие, но просто записано не по порядку, потому что поток 2 ожидает получения блокировки. Я считаю, что завершение вашего приложения в org.apache.log4j.AsyncAppender должно решить эту проблему.

Answer 2

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

sort server.log | more

РЕДАКТИРОВАТЬ: Это полезно для использования в существующих файлах журнала (не для настройки log4j).

Answer 3

Два разных процесса регистрируются в одном и том же файле журнала с помощью обновляемого приложения. Log4j не позволяет этого. В прошлом я разрешал это в кластерном веб-приложении, добавляя имя сервера в файл журнала: appname-server1.log и appname-server2.log, при этом каждый сервер был настроен на запись в свой собственный журнал.

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

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

Answer 4

В ответ на @andy:
(Тема 1) 2009-02-19 14: 54: 27,429 ИНФОРМАЦИЯ [com.catalystwms.tms.services.background.purge.PurgeManager]
(Тема 2) 2009-02-19 14: 47: 01,288 DEBUG [com.catalystwms.core.services.ServiceLocator

то, что я считаю, может происходить, когда поток 2 создает logRecord в 14: 47: 01,288, когда он пытается записать, ему нужно получить блокировку для списка добавляемых в Logger, но другой поток имеет блокировку и занят выполнением. IO, так что поток 2 ждет. поток 14 создает logRecord в 14: 54: 27,429, он пытается получить такую ​​же блокировку и также ждет. Когда блокировка снята, ОС передает ее потоку 1 и печатает.

Если это правда, другая большая проблема связана с производительностью. Пути в коде могут блокироваться при регистрации ввода-вывода.

Answer 5

Вы, вероятно, не сможете исправить это до того, как будет записан журнал. Вы можете попробовать изменить log4J так, чтобы он вызывал .flush () после каждой записи, но это значительно замедлит ваш код, и решение @Chris Nava будет более подходящим.