Log4j: синхронизирован ли он для многопоточных вызовов?

Мы сталкиваемся с интересной проблемой, которую мы заметили при стресс-тестировании нашей системы. Мы очень хорошо используем log4j (в JBOSS) для нашего ведения журнала. Вот наивный пример некоторого ведения журнала, который мы представляем

void someFunction()
{
Log.info("entered some function");
...

Log.info("existed some function");
}

Теперь интересная вещь, которую мы заметили, состоит в том, что если мы запустим 100 потоков против этой функции; вызовы Log.info() блокируют поток. То есть поток 2 ожидает завершения потока1 для вызова "Log.info". В случае Thread 100; он заканчивается в ожидании довольно долго. Мы используем собственный регистратор файлов.

Это известная проблема?

Ответ 1

Log4J должен быть синхронизирован, иначе вы увидите чередующиеся и искаженные сообщения журнала в вашем файле. Но, по крайней мере, в режиме "Резервное копирование" только экземпляры синхронизируются, а не все сообщения о регистрации (поэтому эффективный уровень протокола, сообщение журнала и т.д. Многопоточен).

Однако, даже если синхронизация была удалена, ввод-вывод будет узким местом, поскольку он по сути является однопоточным. Таким образом, рассмотрите возможность уменьшения количества ведения журнала, поскольку это медленный доступ к файлу, а не Log4J.

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

Ответ 2

Что вам может понадобиться - это асинхронное ведение журнала, см. эту статью о том, как это сделать:

Асинхронный журнал с log4j

Также рассмотрим использование правильных уровней журнала. Операторы entered... и exi(s)ted... обычно должны регистрироваться на уровне TRACE, что может быть удобно при отладке (затем установите configure log4j для входа на уровень TRACE). В производственной настройке вы можете указать log4j для регистрации только с уровня INFO или DEBUG, тем самым избегая ненужных действий журнала.

См. также этот вопрос о производительности log4j:

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

Ответ 3

Другие уже предложили вам альтернативы, я копал исходный код и действительно есть раздел synchronized:

public void info(Object message) {
    if(repository.isDisabled(Level.INFO_INT))
       return;
    if(Level.INFO.isGreaterOrEqual(this.getEffectiveLevel()))
       forcedLog(FQCN, Level.INFO, message, null);
}

...

protected void forcedLog(String fqcn, Priority level, Object message, Throwable t) {
    callAppenders(new LoggingEvent(fqcn, this, level, message, t));
}

...

public void callAppenders(LoggingEvent event) {
    int writes = 0;

    for(Category c = this; c != null; c=c.parent) {
        // Protected against simultaneous call to addAppender, removeAppender,...
        synchronized(c) {
            if(c.aai != null) {
                writes += c.aai.appendLoopOnAppenders(event);
            }
            if(!c.additive) {
                break;
            }
        }
    }

    if(writes == 0) {
        repository.emitNoAppenderWarning(this);
    }
}

Ответ 4

Да, log4j использует многопоточную синхронизацию. И не совсем, иногда.

Мы столкнулись с некоторой деградацией производительности, вызванной конфликтом для блокировок log4j и даже взаимоблокировок с использованием сложного метода toString().

См. https://issues.apache.org/bugzilla/show_bug.cgi?id=24159 и https://issues.apache.org/bugzilla/show_bug.cgi?id=41214#c38, например.

Подробнее в моем другом ответе: Файл настроек производительности для log4j?

Я думаю, что это одна из причин существования журнала и переход на пользовательский лог-менеджер с JBoss AS 6.

Ответ 5

Согласитесь с предыдущими ответами. Одним из первых шагов улучшения производительности в любом приложении является уменьшение уровня журнала и сокращение дампов журналов. Разработчики приложений должны стараться использовать правильные уровни регистрации. Ведение журнала имеет огромное влияние на производительность из-за ввода-вывода, а также синхронизации, особенно когда объекты журнала статичны и разделены между различными потоками.