ReSQL.ru
     
powered by simpleCommunicator - 2.0.61     © 2026 Programmizd 02
Мобильная версия    Контакт    Правила    FAQ    Помощь
Целевая тема:
Создать новую тему:
Автор:
Закрыть
Цитировать
Доб. в избранное | Игнор. тему | Прикреп. тему | Пометить прочит. / непрочит. | Фильтр
Форумы / Java [игнор отключен] [закрыт для гостей] / Нетормозящее логирование в Джаве.
25 сообщений из 72, страница 1 из 3
  1  все
Нетормозящее логирование в Джаве.
    #39103628
Dymytry
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Dymytry
Участник
Всем хороших выходных!

Решил на досуге изучить вопрос влияния логгирования на производительность.

Имею простой пустой цикл..
Код: java
1.
2.
        for (i = 0; i<Integer.MAX_VALUE; i++) {
        }


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

1) просто вставить system.out.println() в цикл. замедляет очень сильно.
2) создать надзирающий daemon поток который печатает эту переменную, она должна быть volatile как по учебнику, замедляет прилично.
3) то же, но переменная без volatile. Ухудшение раз в 10 меньше чем в п.2. Оно почти не связано с потоком, а связано что переменная теперь не локальная.

Что я узнать-то хотел.

1) Какой оптимальный алгоритм для реализации этой задачи? Лучше все-таки логгировать из основного потока, или из наблюдающего потока? Предполагаю, библиотеки логгирования решают эту задачу, или есть смысл делать как я?
2) Оказалось, что запись в статическую переменную класса относительно записи в локальную переменную замедляет данный код раз в тыщу. Где бы почитать про Джаву на таком уровне?

Код: java
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
package performance.simple;
public class PerformanceCheck {

    private static int i = 0; //volatile hits performance

    private static final Thread t = new Thread() {
        public void run() {
            while(true) {
                if (i % 100000000 == 0) {
                    System.out.println(i);
                }
            }
        }
    };

    public static void main(String[] args) {

        System.out.println("start execution....");

        t.setDaemon(true);
        t.start();

        long start = System.currentTimeMillis();

        for (i = 0; i<Integer.MAX_VALUE; i++) {
        }

        long end = System.currentTimeMillis();

        System.out.println(end - start);

        System.out.println("end execution....");
    }
}
...
Рейтинг: 0 / 0
14.11.2015, 21:42
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39103678
Фотография Dmitry.
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Dmitry.
Участник
вынести условие
Код: java
1.
if (i % 100000000 == 0)

в основной цикл
...
Рейтинг: 0 / 0
15.11.2015, 00:31
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39103724
rfq
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
rfq
Участник
Dymytry,

https://github.com/OpenHFT/Chronicle-Logger
...
Рейтинг: 0 / 0
15.11.2015, 10:59
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39103786
chabapok
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
chabapok
Участник
условие i % 100000000 не совместимо с "максимально подробно логгировать"

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

Принцип может быть такой. Данные логов кладутся в очередь в том же потоке, а потом (через время или по достижении порогового размера) другой поток их забирает и пишет в лог.
при этом, до некоторой величины граничного потока данных, оно тормозить не будет - пока старая порция будет успевать залоггироваться. Когда поток данных превысит эту величину, то все начнет тормозить - но это уже будет подход к границе производительности.

насчет волатильных переменных, скоростей записи, чтения, публикации в др потоки - смотрите на ютуб ранние видео с канала JUGRuVideo, а так же поиском пробивайте имена людей, которые эти доклады делают.
...
Рейтинг: 0 / 0
15.11.2015, 14:21
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39104032
Фотография Dmitry.
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Dmitry.
Участник
забавно.

следующий код у меня отрабатывает примерно за 13 миллисекунд.
но если заменить
Код: plaintext
if(j==0)j++;
на
Код: plaintext
if(j==0)i++;
то код отрабатывает около 10 секунд.
Код: java
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
public class A {
	
	public static void main(String[] args) {
		System.out.println("start execution....");
		long start = System.currentTimeMillis();
		
		int i=0;
		for (i=0; i<2000000000; i++ ) {
			int j=i%1000000000;
			if(j==0)j++;
		}

		long end = System.currentTimeMillis();
		System.out.println(end - start);
		System.out.println("end execution.... i="+i);
	}
}
...
Рейтинг: 0 / 0
16.11.2015, 01:30
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39104110
Фотография Blazkowicz
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Blazkowicz
Участник
Dymytry1) просто вставить system.out.println() в цикл. замедляет очень сильно.

System.out.println() может выводить в GUI, текстовую консоль, в файл или вообще вникуда. Производительность каждого варианта разная.

Dymytry2) создать надзирающий daemon поток который печатает эту переменную, она должна быть volatile как по учебнику, замедляет прилично.
При чем тут учебник? volatile решает определенную задачу, но для вашей существуют и другие решения, просто вы о них ещё не знаете. Начните хотя бы с ExecutorService

Dymytry3) то же, но переменная без volatile. Ухудшение раз в 10 меньше чем в п.2. Оно почти не связано с потоком, а связано что переменная теперь не локальная.
Понятно что ничего не понятно.

Dymytry1) Какой оптимальный алгоритм для реализации этой задачи?

На сколько я знаю, очереди с буферизированой записью в файл. Логируемое сообщение создаётся в рабочем потоке, никаких volatile для этого не нужно. Сообщение складывается в очередь. Фоновый поток логгера выгребает сообщения и пачкой пишет их в файл.

DymytryЛучше все-таки логгировать из основного потока, или из наблюдающего потока?

Почему именно "наблюдающего"? Других вариантов нет?

DymytryПредполагаю, библиотеки логгирования решают эту задачу, или есть смысл делать как я?

Смысла делать как вы нет. Даже самый древний log4j спокойно пишет сотни мегабайт логов в течении максимум пары секунд (в зависимости от устройства IO)

Dymytry2) Оказалось, что запись в статическую переменную класса относительно записи в локальную переменную замедляет данный код раз в тыщу. Где бы почитать про Джаву на таком уровне?

Ключевые слова для Google
JIT, microbenchmarking, JMH, client JVM, server JVM
...
Рейтинг: 0 / 0
16.11.2015, 09:27
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39104435
Partisan M
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Partisan M
Участник
DymytryРешил на досуге изучить вопрос влияния логгирования на производительность.

Имею простой пустой цикл..

for (i = 0; i<Integer.MAX_VALUE; i++) {
}


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

Лучше на досуге поизучайте русский язык. Ваше изучение импакта не имеет смысла (нот хавает нифига тхе сенсе), поскольку пример не имеет отношения к реальным задачам. Если они у вас есть, то изучайте на них. Но в общем можно сказать, что и в крупных программах это обычно не проблема, однако есть средства предотвращения излишней нагрузки от логирования, их и надо изучить.
А именно:
1) Разделить сообщения на уровни. В настройках логирования (лучше в отдельном файле, а не в и исходном коде программы) для обычной эксплуатации указать более высокий уровень (меньше сообщений), а при обнаружении ошибок сменить его на менее высокий. в популярной библиотеке log4j надо использовать как минимум 2 уровня - ERROR и DEBUG. В других посмотреть, какие там есть уровни.
2) Задать, чтобы команды логирования срабатывали только при достаточном уровне.
Например, в log4j (или LogBack) это будет выглядеть как:

Код: java
1.
2.
3.
if (logger.isDebugEnabled()) {
    logger.debug(какое-то сообщение);
}



Эта предосторжность может иметь смысл, если для создания сообщения требуется существенная работа.
3) Вместо log4j (самая популярная библиотека) по возможности использовать LogBack (автор log4j и LogBack утверждает, что LogBack быстрее. Я не проверял).
...
Рейтинг: 0 / 0
16.11.2015, 13:42
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39104459
Фотография Petro123
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Petro123
Участник
Partisan Mпоскольку пример не имеет отношения к реальным задачам. Если они у вас есть, то изучайте на них
+1
...
Рейтинг: 0 / 0
16.11.2015, 13:56
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39104574
Фотография mayton
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
mayton
Участник
DymytryВсем хороших выходных!
... и хочу максимально подробно логгировать переменную i, с минимальным импактом на производительность.

1) просто вставить system.out.println() в цикл. замедляет очень сильно.
2) создать надзирающий daemon поток который печатает эту переменную, она должна быть volatile как по учебнику, замедляет прилично.
3) то же, но переменная без volatile. Ухудшение раз в 10 меньше чем в п.2. Оно почти не связано с потоком, а связано что переменная теперь не локальная.

Что я узнать-то хотел.

1) Какой оптимальный алгоритм для реализации этой задачи? Лучше все-таки логгировать из основного потока, или из наблюдающего потока? Предполагаю, библиотеки логгирования решают эту задачу, или есть смысл делать как я?
2) Оказалось, что запись в статическую переменную класса относительно записи в локальную переменную замедляет данный код раз в тыщу. Где бы почитать про Джаву на таком уровне?

Оптимизацию логгирования я-бы начал со следующего.
1) Выбор библиотеки логгирования. Что есть? Тут сравнение по перформансу. Log4j, LogBack, Log4j2
https://logging.apache.org/log4j/2.x/performance.html
Обрати внимание на "Asynchronous Logging Performance Improvements".

Можно также посмотреть какие стоят Appenders. Файловые - достаточно быстры.
Но JDBCAppender, SNMPAppender, и пищущие в сислог операционки будут скорее
всего буферизироваться а по заполнении буфера тормозить и блокировать нормальный
flow алгоритма.

2) Пересмотреть смысл самой задачи. Если ты борешся с проблемой то ее надо "вычленить".
Незачем логгировать простыню трафика типа "entry-exit" в каждый codeblock, callback, или сеттер.
Что потом делать с такой аналиткой? Не хватит никаких терабайтов чтобы это хранить.

Имеет смысл сделать логгирование избирательным. Логгировать СОБЫТИЕ.
Например

Код: java
1.
if (i==...) { logger.trace(....) }.



3) Убрать строковые операции и лишнее форматирование. В старых библиотеках. Мы делали конкатенацию

Код: java
1.
javaUtilLogger.fine("i = "+i);



И чтобы отсекать конкатенацию для level > fine от более строгих нужно было оборачивать вызов логгирования
проверкой условия.

В новых библиотеках есть гарантия того что строковая операция и форматирование не будет
работать для "отсекаемых" уровней если мы используем специальный синтаксис с multiple arguments и bracers.

Код: java
1.
slf4jLogger.trace("i = {}",i);
...
Рейтинг: 0 / 0
16.11.2015, 15:20
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39104870
Basil A. Sidorov
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Basil A. Sidorov
Участник
 
Test.java
Код: sql
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
import org.apache.log4j.Logger;
import org.apache.log4j.Level;
public class Test
{
  public static void main(String[] args)
  {
    int count = 100;
    try {
      count = Integer.parseInt(args[0]);
    }
    catch (RuntimeException ex) {};
    long start = System.currentTimeMillis();
    Logger log = Logger.getLogger(Test.class);
    for (int i = 0; i < count; i++) {
      log.trace(Level.TRACE + ": " + i);
      log.debug(Level.DEBUG + ": " + i);
      log.info(Level.INFO + " : " + i);
      log.warn(Level.WARN + " : " + i);
      log.error(Level.ERROR + ": " + i);
      log.fatal(Level.FATAL + ": " + i);
    }
    start = System.currentTimeMillis() - start;
    log.fatal("===========");
    log.fatal("Test run in " + start + " msec.");
    log.shutdown();
  }
}


 
log4.xml
Код: xml
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
<?xml version="1.0" encoding="windows-1251"?>
<!DOCTYPE log4j:configuration PUBLIC "-//APACHE//DTD LOG4J 1.2//EN" "log4j.dtd">

<log4j:configuration debug="false">

  <appender name="console" class="org.apache.log4j.ConsoleAppender">
    <param name="Threshold" value="fatal" />
    <layout class="org.apache.log4j.EnhancedPatternLayout">
      <param name="ConversionPattern" value="|%d{yyyy-MM-dd HH:mm:ss.SSS Z}|%-5p|%t|%c|%m%n%throwable{short}" />
    </layout>
  </appender>

  <appender name="null" class="org.apache.log4j.varia.NullAppender">
    <layout class="org.apache.log4j.EnhancedPatternLayout">
      <param name="ConversionPattern" value="|%d{yyyy-MM-dd HH:mm:ss.SSS Z}|%-5p|%t|%c|%m%n" />
    </layout>
  </appender>

  <appender name="file" class="org.apache.log4j.FileAppender">
    <param name="File" value="Test.log" />
    <param name="Append" value="false" />
    <layout class="org.apache.log4j.EnhancedPatternLayout">
      <param name="ConversionPattern" value="|%d{yyyy-MM-dd HH:mm:ss.SSS Z}|%-5p|%c|%t|%m%n" />
    </layout>
  </appender>

  <appender name="ASYNC" class="org.apache.log4j.AsyncAppender">
    <appender-ref ref="null" />
    <appender-ref ref="file" />
    <appender-ref ref="console"/>
  </appender>

  <root>
    <priority value="trace"/>
    <appender-ref ref="ASYNC"/>
  </root>

</log4j:configuration>


Сотня итераций, вывод на экран (FATAL), в файл и nullAppender (TRACE):
Код: plaintext
1.
2.
...
|2015-11-16 23:22:39.040 +0800|FATAL|main|Test|===========
|2015-11-16 23:22:39.040 +0800|FATAL|main|Test|Test run in 267 msec.

Всё тоже самое, кроме уровня (везде FATAL):
Код: plaintext
1.
2.
...
|2015-11-16 23:23:39.136 +0800|FATAL|main|Test|===========
|2015-11-16 23:23:39.136 +0800|FATAL|main|Test|Test run in 187 msec.

P.S. AsyncLogger настраивается только через xml-конфигурацию.
Создаётся (перезаписывается) файл Test.log в текущем каталоге.
...
Рейтинг: 0 / 0
16.11.2015, 18:35
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39104926
Basil A. Sidorov
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Basil A. Sidorov
Участник
Лучше так (без предупреждений об устаревшем API):
 
Код: sql
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
import org.apache.log4j.Level;
import org.apache.log4j.Logger;
import org.apache.log4j.LogManager;
public class Test
{
  final static LogManager logMan = new LogManager();
  public static void main(String[] args)
  {
    int count = 100;
    try {
      count = Integer.parseInt(args[0]);
    }
    catch (RuntimeException ex) {};
    long start = System.currentTimeMillis();
    Logger log = logMan.getLogger(Test.class);
    for (int i = 0; i < count; i++) {
      log.trace(Level.TRACE + ": " + i);
      log.debug(Level.DEBUG + ": " + i);
      log.info(Level.INFO + " : " + i);
      log.warn(Level.WARN + " : " + i);
      log.error(Level.ERROR + ": " + i);
      log.fatal(Level.FATAL + ": " + i);
    }
    start = System.currentTimeMillis() - start;
    log.fatal("===========");
    log.fatal("Test run in " + start + " msec.");
    logMan.shutdown();
  }
}


Ну и замеры времени более "честные" - исключены (фиксированные) затраты времени на создание конфигурации и получение логгеров.
...
Рейтинг: 0 / 0
16.11.2015, 19:19
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39104933
Basil A. Sidorov
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Basil A. Sidorov
Участник
Ну и совсем косметика:
 
Test.java
Код: sql
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
import org.apache.log4j.Level;
import org.apache.log4j.Logger;
import org.apache.log4j.LogManager;
public class Test
{
  final static LogManager logMgr = new LogManager();
  final static Logger log = logMgr.getLogger(Test.class);
  public static void main(String[] args)
  {
    int count = 100;
    try {
      count = Integer.parseInt(args[0]);
    }
    catch (RuntimeException ex) {};
    long start = System.currentTimeMillis();
    for (int i = 0; i < count; i++) {
      log.trace(Level.TRACE + ": " + i);
      log.debug(Level.DEBUG + ": " + i);
      log.info(Level.INFO + " : " + i);
      log.warn(Level.WARN + " : " + i);
      log.error(Level.ERROR + ": " + i);
      log.fatal(Level.FATAL + ": " + i);
    }
    start = System.currentTimeMillis() - start;
    log.fatal("===========");
    log.fatal("Test run in " + start + " msec.");
    logMgr.shutdown();
  }
}

...
Рейтинг: 0 / 0
16.11.2015, 19:24
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39104936
scf
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
scf
Участник
rfq,

О да, всё придумано до нас.
...
Рейтинг: 0 / 0
16.11.2015, 19:30
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39104939
Basil A. Sidorov
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Basil A. Sidorov
Участник
Консоль штука медленная, поэтому запускать лучше так (windows):
Код: plaintext
1.
2.
3.
4.
> java ... 1000|find "|Test run "
|2015-11-17 00:33:02.403 +0800|FATAL|main|Test|Test run 1000 iteration in 63 msec.

> java ... Test 1000|find "|Test run "
|2015-11-17 00:33:27.818 +0800|FATAL|main|Test|Test run 1000 iteration in 109 msec.
...
Рейтинг: 0 / 0
16.11.2015, 19:35
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39105037
Фотография grasoff.net
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
grasoff.net
Участник
Dymytryс минимальным импактомс чем? о_О
...
Рейтинг: 0 / 0
16.11.2015, 22:57
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39105834
Basil A. Sidorov
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Basil A. Sidorov
Участник
 
Более содержательный пример
Код: sql
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.
43.
44.
45.
46.
47.
48.
49.
50.
51.
52.
53.
54.
55.
56.
57.
58.
59.
60.
61.
62.
63.
64.
65.
66.
67.
68.
import org.apache.log4j.Level;
import org.apache.log4j.Logger;
import org.apache.log4j.LogManager;
import java.util.concurrent.atomic.AtomicInteger;

public class Test
{
  private final static int
    THREADS_MIN = 1
  , THREADS_MAX = 5000
  , THREADS_DEFAULT = 10
  , COUNTER_MIN = 1000
  , COUNTER_MAX = 1000000
  , COUNTER_DEFAULT = COUNTER_MAX;
  
  final static LogManager logMgr = new LogManager();
  private final static Logger log = logMgr.getLogger(Test.class);
  
  static int threads = THREADS_DEFAULT;
  static int count = COUNTER_DEFAULT;
  static AtomicInteger counter = new AtomicInteger(0);

  public static void main(String[] args) throws InterruptedException
  {
    try { threads = Integer.parseInt(args[0]); }
    catch (RuntimeException e) {};
    if (threads < THREADS_MIN) threads = THREADS_MIN;
    if (threads > THREADS_MAX) threads = THREADS_MAX;

    try { count = Integer.parseInt(args[1]); }
    catch (RuntimeException e) {};
    if (count < COUNTER_MIN) count = COUNTER_MIN;
    if (count > COUNTER_MAX) count = COUNTER_MAX;
    
    Thread[] loggers = new Thread[threads];
    for (int i = 0; i < threads; i++) loggers[i] = new Thread(new LogPlain());
    long timer = System.currentTimeMillis();
    for (Thread logger : loggers) logger.start();
    for (Thread logger : loggers) logger.join();
    timer = System.currentTimeMillis() - timer;
    log.fatal("Test run " + count + " iteration on " + threads + " threads in " + timer + " msec");
    logMgr.shutdown();
  }
  
  private static class LogPlain implements Runnable
  {
    private final static Logger log = logMgr.getLogger(LogPlain.class);
    @Override public void run()
    {
      int i;
      for (;;)
      {
        if (count < (i = counter.incrementAndGet())) return;
        log.fatal(Level.FATAL + ": " + i + " " + Thread.currentThread());
        if (count < (i = counter.incrementAndGet())) return;
        log.error(Level.ERROR + ": " + i);
        if (count < (i = counter.incrementAndGet())) return;
        log.warn (Level.WARN + " : " + i);
        if (count < (i = counter.incrementAndGet())) return;
        log.info (Level.INFO + " : " + i);
        if (count < (i = counter.incrementAndGet())) return;
        log.debug(Level.DEBUG + ": " + i);
        if (count < (i = counter.incrementAndGet())) return;
        log.trace(Level.TRACE + ": " + i);
      }
    }
  }
}

Результаты:

Код: plaintext
1.
2.
3.
4.
5.
 (for %A in (1 10 50 100 500) do @java -cp bin;classes Test %A)|find "|Test run "
2015-11-17 22:39:57.535 +0800|FATAL|main|Test|Test run 1000000 iteration on 1 threads in 6396 msec
2015-11-17 22:40:05.527 +0800|FATAL|main|Test|Test run 1000000 iteration on 10 threads in 6429 msec
2015-11-17 22:40:13.657 +0800|FATAL|main|Test|Test run 1000000 iteration on 50 threads in 6583 msec
2015-11-17 22:40:22.225 +0800|FATAL|main|Test|Test run 1000000 iteration on 100 threads in 7067 msec
2015-11-17 22:40:30.246 +0800|FATAL|main|Test|Test run 1000000 iteration on 500 threads in 6474 msec

Если я нигде не накосячил (судя по файловому логу - не накосячил), то, в нулевом приближении, AsycnLogger - вполне эффективен.
...
Рейтинг: 0 / 0
17.11.2015, 17:47
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39106025
Dymytry
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Dymytry
Участник
Всем большое спасибо!

Пойду изучать исходники библиотек логгирования.
...
Рейтинг: 0 / 0
17.11.2015, 21:56
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39106650
Сергей Арсеньев
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Сергей Арсеньев
Участник
IMHO логгирование показывает весь блеск и нищету кофе-машины.

С одной стороны JIT. Казалось бы сделай макросы условную компиляции управляемые из Runtime. И при их изменении инвалидируй скомпилированный код использовавший их и компилируй заново.

Ан нет.
...
Рейтинг: 0 / 0
18.11.2015, 14:20
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39106712
Фотография mayton
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
mayton
Участник
Сергей АрсеньевIMHO логгирование показывает весь блеск и нищету кофе-машины.

С одной стороны JIT. Казалось бы сделай макросы условную компиляции управляемые из Runtime. И при их изменении инвалидируй скомпилированный код использовавший их и компилируй заново.

Ан нет.
Тут кофеварка непричём. Подобный антипаттерн еще легче воспроизводить в языках и системах с двухэтапной компилляцией.
А как вариант можно сделать как в ojdbc. Собрать два варианта библиотек. ojdbc_g где включено JUL и ojdbc где вызовы
логгеров отсутствуют. В конце-концов манипулирование логами уровня трейс это достаточно специфичная задача
и ее можно вынести в цикл конфигурирования приложения.

Управляемая компилляция из Runtime это мега-круто но ненужно. Это ... как ипошить по птичкам из САУ.
...
Рейтинг: 0 / 0
18.11.2015, 14:51
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39106738
Сергей Арсеньев
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Сергей Арсеньев
Участник
maytonТут кофеварка непричём. Подобный антипаттерн еще легче воспроизводить в языках и системах с двухэтапной компилляцией.

Ну рвет твои шаблоны экстремальное логгирование. Но это не значит, что это что-то не реализуемое.

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

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

Но если нужна максимальная производительность, то надо убирать генерацию параметров. А это без динамического компилирования - только компиляцией для всех уровней. Каждого класса. И соответствующего class loader.

Самое смешное, что в кофемашине, обычно, есть динамическая компиляция. Но программиста до нее не допускают. :)
...
Рейтинг: 0 / 0
18.11.2015, 15:01
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39106833
Partisan M
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Partisan M
Участник
DymytryПойду изучать исходники библиотек логгирования.

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

Сергей АрсеньевIMHO логгирование показывает весь блеск и нищету кофе-машины.
Мне оно показывает только результат логирования. Блеск и нищета если и есть, то не интересуют.


Да, забыл. При выводе по формату на скорость может влиять выбор форматов.
Например, в log4j для даты (%d) автор рекомендует один из форматов - ABSOLUTE, DATE, ISO8601. Можно задать любой, представимый с помощью SimpleDateFormat, но другие по мнению автора медленнее. Он очевидно измерял, а я нет и эту рекомендацию соблюдаю не всегда, больше обращаю внимание на удобство.

Также он предупреждает о возможной медлительности элементов формата C, F, l, L, M.
...
Рейтинг: 0 / 0
18.11.2015, 15:47
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39107032
Basil A. Sidorov
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Basil A. Sidorov
Участник
Сергей АрсеньевОсновной оверхед будет в генерации параметров для log.debug(...) и т.п.Можно озвучить экзотическую конфигурацию, где ввод-вывод перестал быть узким местом?Самое смешное, что в кофемашине, обычно, есть динамическая компиляция. Но программиста до нее не допускают. :)А вы уже научились использовать серверную JVM?
...
Рейтинг: 0 / 0
18.11.2015, 17:36
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39107070
Basil A. Sidorov
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Basil A. Sidorov
Участник
К вопросу об охрененных затратах на обработку параметров:
Код: plaintext
1.
2.
3.
4.
5.
6.
> for %A in (1 50 100 500 1000 5000) do @java -cp bin;classes Test %A
Test run 1000000 iteration on 1 threads in 1357 msec
Test run 1000000 iteration on 50 threads in 1420 msec
Test run 1000000 iteration on 100 threads in 1466 msec
Test run 1000000 iteration on 500 threads in 1513 msec
Test run 1000000 iteration on 1000 threads in 1327 msec
Test run 1000000 iteration on 5000 threads in 2605 msec
 
Test.java
Код: sql
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.
43.
44.
45.
46.
47.
48.
49.
50.
51.
52.
53.
54.
55.
56.
57.
58.
59.
60.
61.
62.
63.
64.
65.
66.
67.
68.
69.
import org.apache.log4j.Level;
import org.apache.log4j.Logger;
import org.apache.log4j.LogManager;
import java.util.concurrent.atomic.AtomicInteger;

public class Test
{
  private final static int
    THREADS_MIN = 1
  , THREADS_MAX = 5000
  , THREADS_DEFAULT = 10
  , COUNTER_MIN = 1000
  , COUNTER_MAX = 1000000
  , COUNTER_DEFAULT = COUNTER_MAX;
  
  final static LogManager logMgr = new LogManager();
  private final static Logger log = logMgr.getLogger(Test.class);
  
  static int threads = THREADS_DEFAULT;
  static int count = COUNTER_DEFAULT;
  static AtomicInteger counter = new AtomicInteger(0);

  public static void main(String[] args) throws InterruptedException
  {
    try { threads = Integer.parseInt(args[0]); }
    catch (RuntimeException e) {};
    if (threads < THREADS_MIN) threads = THREADS_MIN;
    if (threads > THREADS_MAX) threads = THREADS_MAX;

    try { count = Integer.parseInt(args[1]); }
    catch (RuntimeException e) {};
    if (count < COUNTER_MIN) count = COUNTER_MIN;
    if (count > COUNTER_MAX) count = COUNTER_MAX;
    
    Thread[] loggers = new Thread[threads];
    for (int i = 0; i < threads; i++) loggers[i] = new Thread(new LogPlain());
    long timer = System.currentTimeMillis();
    for (Thread logger : loggers) logger.start();
    for (Thread logger : loggers) logger.join();
    timer = System.currentTimeMillis() - timer;
    logMgr.shutdown();
    System.err.println("Test run " + count + " iteration on " + threads + " threads in " + timer + " msec");
  }
  
  private static class LogPlain implements Runnable
  {
    private final static Logger log = logMgr.getLogger(LogPlain.class);
    @Override public void run()
    {
      int i;
      for (;;)
      {
        if (count < (i = counter.incrementAndGet())) return;
        Thread.yield();
        log.fatal(Level.FATAL + ": " + i + " " + Thread.currentThread());
        if (count < (i = counter.incrementAndGet())) return;
        log.error(Level.ERROR + ": " + i);
        if (count < (i = counter.incrementAndGet())) return;
        log.warn (Level.WARN + " : " + i);
        if (count < (i = counter.incrementAndGet())) return;
        log.info (Level.INFO + " : " + i);
        if (count < (i = counter.incrementAndGet())) return;
        log.debug(Level.DEBUG + ": " + i);
        if (count < (i = counter.incrementAndGet())) return;
        log.trace(Level.TRACE + ": " + i);
      }
    }
  }
}

 
log4j.xml
Код: xml
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
<?xml version="1.0" encoding="windows-1251"?>
<!DOCTYPE log4j:configuration PUBLIC "-//APACHE//DTD LOG4J 1.2//EN" "log4j.dtd">

<log4j:configuration debug="false">

  <appender name="console" class="org.apache.log4j.ConsoleAppender">
    <param name="Threshold" value="fatal" />
    <layout class="org.apache.log4j.EnhancedPatternLayout">
      <param name="ConversionPattern" value="|%d{yyyy-MM-dd HH:mm:ss.SSS Z}|%-5p|%t|%c|%m%n%throwable{short}" />
    </layout>
  </appender>

  <appender name="null" class="org.apache.log4j.varia.NullAppender">
    <layout class="org.apache.log4j.EnhancedPatternLayout">
      <param name="ConversionPattern" value="|%d{yyyy-MM-dd HH:mm:ss.SSS Z}|%-5p|%t|%c|%m%n" />
    </layout>
  </appender>

  <appender name="ASYNC" class="org.apache.log4j.AsyncAppender">
    <appender-ref ref="null" />
    <!-- appender-ref ref="file" / -->
    <!-- appender-ref ref="console"/ -->
  </appender>

  <appender name="file" class="org.apache.log4j.FileAppender">
    <param name="File" value="Test.log" />
    <param name="Append" value="false" />
    <layout class="org.apache.log4j.EnhancedPatternLayout">
      <param name="ConversionPattern" value="|%d{yyyy-MM-dd HH:mm:ss.SSS Z}|%-5p|%c|%t|%m%n" />
    </layout>
  </appender>

  <root>
    <priority value="trace"/>
    <appender-ref ref="ASYNC"/>
  </root>

</log4j:configuration>

...
Рейтинг: 0 / 0
18.11.2015, 17:59
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39107074
Basil A. Sidorov
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Basil A. Sidorov
Участник
В предыдущем примере уровень логирования был "trace", ставим "off" ничего более не меняя:
Код: plaintext
1.
2.
3.
4.
5.
6.
> for %A in (1 50 100 500 1000 5000) do @java -cp bin;classes Test %A
Test run 1000000 iteration on 1 threads in 343 msec
Test run 1000000 iteration on 50 threads in 437 msec
Test run 1000000 iteration on 100 threads in 515 msec
Test run 1000000 iteration on 500 threads in 702 msec
Test run 1000000 iteration on 1000 threads in 983 msec
Test run 1000000 iteration on 5000 threads in 1763 msec
...
Рейтинг: 0 / 0
18.11.2015, 18:03
| Ответить | Цитировать | Написать  
Нетормозящее логирование в Джаве.
    #39107413
Сергей Арсеньев
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Сергей Арсеньев
Участник
Basil A. SidorovМожно озвучить экзотическую конфигурацию, где ввод-вывод перестал быть узким местом?
Если вывод в журнал идет на отдельный канал ввода-вывода с независимым массивом дисков и основной поток занят работой, а не только сбросом информации в журнал. То могут быть ситуации, когда ввод-вывод журнала не будет узким местом. Но конечно не панацея.
Basil A. SidorovСамое смешное, что в кофемашине, обычно, есть динамическая компиляция. Но программиста до нее не допускают. :)А вы уже научились использовать серверную JVM?
Нет. Я конечно представляю себе как встроить препроцессор который будет высматривать в коде макросы условной компиляции перед передачей их javac и как устроить инвалидацию загруженных классов в класслоадере и подсовывание прошедших компиляцию через препроцессор. Но чисто теоретически. На практике до такой фигни руки не доходили. И вряд ли дойдут.
...
Рейтинг: 0 / 0
19.11.2015, 10:09
| Ответить | Цитировать | Написать  
25 сообщений из 72, страница 1 из 3
  1  все
Форумы / Java [игнор отключен] [закрыт для гостей] / Нетормозящее логирование в Джаве.
Найденые пользователи ...
Разблокировать пользователей ...
Читали тему (0):
Читали форум (0):
Пользователи онлайн (0):
Польз. соглашение   Полит. конфиден.  
NoSQL.ru       Кролег: Проекты, Новости, Чат       РЕД ФОРУМ       Фотоальбом: Участники, Встречи
Закрыть
start [/forum/topic.php?fid=59&msg=39104936&tid=2124392]:
 0ms
get settings:
 9ms
get forum list:
 15ms
check forum access:
 4ms
check topic access:
 4ms
track hit:
 65ms
get topic data:
 12ms
get forum data:
 3ms
get page messages:
 77ms
get tp. blocked users:
 1ms
others: 221ms
total:  411ms
созд. / загр.: 411ms
x
x
Закрыть


Просмотр
0 / 0
Close
Debug Console [Select Text]