Главная
Блог разработчиков phpBB
 
+ 17 предустановленных модов
+ SEO-оптимизация форума
+ авторизация через соц. сети
+ защита от спама

Продуктивность log4j 1.x в синхронном и асинхронном режиме

Anna | 2.06.2014 | нет комментариев
Доброго времени суток, програжители!

На данный момент я занимаюсь совершенствованием продуктивности большого корпоративного решения. Его особенность разрешает множеству пользователей исполнять аналогичные действия, а соответственно за кулисами, сервер приложений работает с одним и тем же кодом. И вот в один из моментов длинного пути убыстрения приложения, было подмечено что в топе самых низкопроизводительных участков верхние места занимает log4j. Первой мыслью было — излишнее логирование, но дальнейший обзор ее опроверг. Тем больше что это весьма значимые данные для инженеров поддержки, и если убрать это теперь — то либо код вернут обратно либо обзор задач продакшен сервера будет значительно затруднен.

Это и натолкнуло меня на данное изыскание — есть ли метод оптимизировать процесс логирования?

Disclaimerв силу обилия в данной статье диаграмм вызывающих психоделические ассоциации (как бы этой: это не сопоставление синхронного и асинхронного режимов логирования, здесь дракон убивает змею!), не рекомендуется к просмотру несовершеннолетним, людям с неустойчивой психикой и беременным женщинам, чей код теснее в продакшене а выдача ближайшего патча не в этом году.

Осмотрительно, под катом трафик.

В чем же повод?

Как традиционно повод тривиальна — «конкурентный доступ». Позже нескольких экспериментов с плавающим числом параллельных потоков стало ясно, что время работы вызова логирования не линейно, соответственно итог — ЖД крепко проигрывает.

Вот итоги замеров:

Каково решение?

Искать другие методы логирования, проводить апгрейд библиотек, это все делать дозволено, но задача в том что бы достичь максимум итога при минимуме усилий. О библиотеке «log4j 2» я тоже могу поведать, но это будет отдельной статьей. Теперь же мы разглядим средства предоставляемые нам «из коробки» в log4j 1.x.

Среди поставляемых с библиотекой аппендеров есть AsyncAppender, тот, что разрешает, применяя промежуточный буфер для накопления событий логирования, организовать асинхронную работу с файловой системой (если финальный аппендер именно файловый, чай первоначально он задумывался для SMTP логгера). Порождаясь, события логирования накапливаются, и лишь при достижении определенного яруса заполненности буфера — попадают в файл.

Замеры

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

Мерить будем так:
0) Предварительно предупреждаю, «прекрасных данных я не делал», местами видно что процессор переключался на иную работу, и эти места я оставил как было. Это чай тоже часть реальной работы системы.
1) Тесты разобьем на 3 группы:
— 10 событий логирования (от 1 до 10 с шагом 1)
— 550 событий логирования (от 10 до 100 с шагом 10)
— 5500 событий логирования (от 100 до 1000 с шагом 100)
2) В всякой группе будет 3 подгруппы тестов — в зависимости от объема буфера (испробуем обнаружить наилучший):
— 500 событий
— 1500 событий
— 5000 событий
3) Тесты будут выполняться синхронно и асинхронно.

Синхронная конфигурация логгера

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd" >
<log4j:configuration>
    <appender name="fileAppender">
        <param name="file" value="st.log"/>
        <layout>
            <param name="ConversionPattern" value="%d{ABSOLUTE} %5p %t %c{1}:%M:%L - %m%n"/>
        </layout>
    </appender>
    <root>
        <priority value="info" />
        <appender-ref ref="fileAppender"/>
    </root>
</log4j:configuration>
Асинхронная конфигурация логгера

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd" >
<log4j:configuration>
    <appender name="fileAppender">
        <param name="file" value="st.log"/>
        <layout>
            <param name="ConversionPattern" value="%d{ABSOLUTE} %5p %t %c{1}:%M:%L - %m%n"/>
        </layout>
    </appender>
    <appender name="ASYNC">
        <param name="BufferSize" value="500"/>
        <appender-ref ref="fileAppender"/>
    </appender>
    <root>
        <priority value="info" />
        <appender-ref ref="ASYNC"/>
    </root>
</log4j:configuration>

4) Сами тесты представляют собой примитивные вызовы логирования вперемешку со «случайной работой» (продолжительностью от 1 до 15 мс, что бы иметь вероятность чередовать доступ к файлу).

Начальный код теста

package com.ice.logger_test;

import org.apache.commons.lang3.time.StopWatch;
import org.apache.log4j.Logger;

import java.util.Random;

public class SimpleTest {

    private static Logger logger = Logger.getLogger(SimpleTest.class);
    private static double NANOS_TO_SEC = 1000000000.0d;
    private static String LOG_MESSAGE =
            "One hundred bytes log message for performing some tests using sync/async appenders of log4j library";

    public static void main(String[] args) throws InterruptedException {
        //performTest("Single thread");

        ThreadRunner t1 = new ThreadRunner();
        new Thread(t1).start();
        new Thread(t1).start();
        new Thread(t1).start();
        new Thread(t1).start();
        new Thread(t1).start();
        new Thread(t1).start();
        new Thread(t1).start();
        new Thread(t1).start();
        new Thread(t1).start();
        new Thread(t1).start();
    }

    private static void performTest(String message) throws InterruptedException {
        logger.info("Warm-up...");
        logger.info("Warm-up...");
        logger.info("Warm-up...");

        StopWatch timer = new StopWatch();
        Random ran = new Random();
        for(int i = 1; i <= 10000; i  = getIncrementator(i)) {
            timer.reset();
            timer.start();
            int iterations = 0;
            for(int j = 1; j <= i; j  ) {
                timer.suspend();
                Thread.sleep(ran.nextInt(15) 1); // some work
                timer.resume();

                logger.info(LOG_MESSAGE);

                timer.suspend();
                Thread.sleep(ran.nextInt(15) 1); // some work
                timer.resume();

                iterations = j;
            }
            timer.stop();
            System.out.printf(message   " %d iteration(s) %f sec\n", iterations, (timer.getNanoTime() / NANOS_TO_SEC));
        }
    }

    private static int getIncrementator(int i) {
        if(i >= 0 && i < 10) return 1;
        if(i >= 10 && i < 100) return 10;
        if(i >= 100 && i < 1000) return 100;
        if(i >= 1000 && i < 10000) return 1000;
        if(i >= 10000 && i <= 100000) return 10000;
        return 0;
    }

    static class ThreadRunner implements Runnable {
        @Override
        public void run() {
            try {
                performTest(Thread.currentThread().getName());
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    }
}

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

Синхронный запуск, 2 потока

Для начала посмотрим как ведет себя логгер в синхронной конфигурации. Запустим все сценарии на 2 потоках.
Вот итоги:

Асинхронный запуск, 2 потока
Буфер = 500

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

Буфер = 1500

Увеличим буфер в 3 раза и проведем те же тесты:

Буфер = 5000

Увеличим буфер в 10 раза и проведем те же тесты:

Результат для 2-х потоков

Сейчас для наглядности я соберу все асинхронные (что бы испробовать определить наилучший буфер) и синхронные (для наглядности, увлекательно чай, кто победи) тесты в одну диаграмму:

Сейчас я думаю наглядно видно убыстрение при асинхронном режиме.
Но раньше чем делать итоги, давайте повторим наши тесты на 5 и 10 потоках.

Синхронный запуск, 5 потоков

Асинхронный запуск, 5 потоков
Буфер = 500

Буфер = 1500

Буфер = 5000

Результат для 5-ти потоков

Синхронный запуск, 10 потоков

Асинхронный запуск, 10 потоков
Буфер = 500

Буфер = 1500

Буфер = 5000

Вывод для 10-х потоков

Итог, как говорится, на лицо.
Раз уж сейчас мы однозначно можем говорить о превосходстве асинхронного метода логирования, то давайте испробуем увеличить объемы тестов еще в 10 раз. Добавим тест на 55000 событий логирования (от 1000 до 10000 с шагом 1000). Буфер возьмем равным 500 (так как он на 1-й взор, а позднее это будет подтверждено, является особенно оптимальным в наших тестах).

Синхронный запуск, 10 потоков на крупных объемах данных




Асинхронный запуск, 10 потоков на крупных объемах данных




Вывод для 10-х потоков на крупных объемах данных




Наилучший буфер

На данный момент у нас теснее накопилось достаточно много статистических данных, следственно давайте усредним их все и посмотрим какой-же буфер особенно подходящий.

2 Потока




5 Потоков




10 Потоков




10 Потоков, огромный объем тестов

Итого — 500 событий, именно наш буфер, разрешающий особенно результативно трудиться в асинхронном режиме.
А сейчас если и совсем сопоставить всеобщее (либо среднее) время работы всех тестов то дозволено получить константу, отображающую порядок выигрыша асинхронного режима перед синхронным, у меня это —8,9 (раз).

Завершение

Вышеизложенный материал дает осознать что тактика асинхронного логирования дает выигрыш продуктивности. Тогда навязывается вопрос — отчего не применять ее неизменно? Для того что бы сделать выбор в пользу того либо другого метода необходимо представлять механизмы которые скрываются внутри. Ниже привожу несколько принципов взятых с оффсайта:
1) AsyncAppender оперирует своим собственным потоком (в то время как сам FileAppender выполняется в контексте нынешнего потока), в связи с этим при его применении желанно повысить лимит потоков сервера приложений.
2) При применении AsyncAppender’а происходят убыточные расходы на память, так как события логирования сбрасываются в файл не мгновенно, а заранее наполнив буфер.
3) Блокировка файла лога длится дольше нежели при применении синхронного подхода, так как буфер сообщений содержит на много огромнее информации для записи.
В тезисе все прозаично, но здесь необходимо понимать что сама по себе синхронизация это тоже блокировка, так что значимо перенося ее из одного места в другое не сделать дрянней.

Используйте асинхронность там где она подлинно необходима:
— долгоиграющие аппендеры — SMTP, JDBC
— всеобщая блокировка источников — FTP, Local File Storage
Но раньше каждого, непременно профилируйте свой код.

Excel версия данной статьи:
docs.google.com/spreadsheet/ccc?key=0AkyN15vTZD-ddHV0Y3p4QVUxTXVZRldPcU0tNzNucWc&usp=sharing
docs.google.com/spreadsheet/ccc?key=0AkyN15vTZD-ddFhGakZsVWRjV1AxeGljdDczQjdNbnc&usp=sharing

Спасибо за внимание. Верю статья будет вам пригодна.
Продуктивной вам недели!

Необходима ли сходственная статья про log4j 2.x?

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

Проголосовало 39 человек. Воздержалось 9 человек.

 

 Источник: programmingmaster.ru
Оставить комментарий
Форум phpBB, русская поддержка форума phpBB
Рейтинг@Mail.ru 2008 - 2017 © BB3x.ru - русская поддержка форума phpBB