Сколько стоит ведение журнала трассировки / отладки в производстве? Какова производительность при записи в файл? В этих тестах я сравниваю влияние производительности на уровни ведения журналов ( error , warn , info , debug , trace ) и добавление журналов (консольное приложение, файловое приложение) в нескольких реальных случаях использования OptaPlanner .
Методология сравнения
- Реализация ведения журнала: SFL4J
1.7.2с Logback 1.0.9 (Logback — духовный преемник Log4J 1) - Конфигурация журнала (
logback.xml):
|
01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
|
<?xml version="1.0" encoding="UTF-8"?><configuration> <appender name="appender" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%d [%t] %-5p %m%n</pattern> </encoder> </appender> <logger name="org.optaplanner" level="info"/> <root level="warn"> <appender-ref ref="appender"/> </root></configuration> |
Что приводит к выводу, как это:
|
1
2
3
4
|
2015-02-23 08:07:35,310 [main] INFO Solving started: time spent (18), best score (uninitialized/0hard/0soft), environment mode (REPRODUCIBLE), random (JDK with seed 0).2015-02-23 08:07:35,363 [main] INFO Construction Heuristic phase (0) ended: step total (6), time spent (71), best score (0hard/-5460soft).2015-02-23 08:07:35,641 [main] INFO Local Search phase (1) ended: step total (1), time spent (349), best score (0hard/-5460soft).2015-02-23 08:07:35,652 [main] INFO Solving ended: time spent (360), best score (0hard/-5460soft), average calculate count per second (905), environment mode (REPRODUCIBLE). |
- Аргументы VM:
-Xmx1536M -server
Программное обеспечение:Linux 3.2.0-59-generic-pae
Аппаратное обеспечение:Intel® Xeon® CPU W3550 @ 3.07GHz - Каждый прогон решает 13 проблем планирования с OptaPlanner . Каждая проблема планирования длится 5 минут. Он начинается с 30-секундного прогрева JVM, который сбрасывается.
- Решение проблемы планирования не требует ввода-вывода (за исключением нескольких миллисекунд во время запуска для загрузки ввода). Один процессор полностью насыщен. Он постоянно создает много недолговечных объектов, и GC собирает их впоследствии.
- Тесты измеряют количество баллов, которое можно рассчитать за миллисекунду. Чем выше, тем лучше. Расчет баллов для предлагаемого решения по планированию нетривиален: он включает в себя множество вычислений, в том числе проверку на конфликты между каждым объектом и любым другим объектом.
Чтобы воспроизвести эти тесты локально, соберите optaplanner из исходного кода и запустите основной класс GeneralOptaPlannerBenchmarkApp .
Уровни ведения журнала: error , warn , info , debug и trace
Я запускал один и тот же набор тестов несколько раз с другим уровнем ведения журнала OptaPlanner :
|
1
|
<logger name="org.optaplanner" level="error|warn|info|debug|trace"/> |
Все остальные библиотеки (включая Drools ) были настроены на ведение журнала предупреждений. Детальность ведения журнала в OptaPlanner сильно различается на уровне:
-
errorиwarn: 0 строк -
info: 4 строки на тест, поэтому менее 1 строки в минуту . -
debug: 1 строка за шаг, поэтому примерно 1 в секунду для поиска по Табу и более для позднего принятия -
trace: 1 строка за ход, поэтому от 1к до 120к в секунду
Это необработанные контрольные цифры, измеряемые в подсчете вычисления среднего балла в секунду (чем выше, тем лучше):
| Уровень ведения журнала | Облако 200с | Облако 800с | Машина Б1 | Машина B10 | Курс с7 | Курс с8 | Экзамен S2 | Экзамен S3 | Медсестра М1 | Медсестра mh1 | Sport nl14 |
|---|---|---|---|---|---|---|---|---|---|---|---|
| ошибка | 66065 | 61866 | 119230 | 32759 | 6282 | 8370 | 10330 | 7121 | 4001 | 3718 | 1248 |
| предостерегать | 66943 | 62191 | 122678 | 32688 | 6297 | 8303 | 10517 | 7182 | 3942 | 3660 | 1278 |
| Информация | 67393 | 63192 | 123734 | 32461 | 6188 | 8299 | 10330 | 7108 | 3944 | 3654 | 1252 |
| отлаживать | 60254 | 55938 | 118917 | 32735 | 6054 | 8062 | 10310 | 7104 | 3904 | 3586 | 1244 |
| след | 25159 | 25214 | 40346 | 20629 | 5585 | 7347 | 9229 | 6642 | 3360 | 3138 | 1156 |
| Масштаб набора данных | 120k | 1920k | 500k | 250000k | 217k | 145k | 1705k | 1613k | 18k | 12k | 4k |
| Алгоритм | Позднее принятие | Позднее принятие | Табу Поиск | Табу Поиск | Позднее принятие | Позднее принятие | Табу Поиск | Табу Поиск | Табу Поиск | Табу Поиск | Табу Поиск |
Я игнорирую разницу между ошибкой, предупреждением и регистрацией информации: разница не более 4%, прогоны воспроизводимы на 100%, и я не использовал компьютер во время бенчмаркинга, поэтому я полагаю, что в разнице можно обвинить компиляция точки доступа JIT или удача процессора.
Сколько стоит включение ведения журнала отладки или трассировки в производительности (в отличие от ведения журнала информации)?
| Уровень ведения журнала | Облако 200с | Облако 800с | Машина Б1 | Машина B10 | Курс с7 | Курс с8 | Экзамен S2 | Экзамен S3 | Медсестра М1 | Медсестра mh1 | Sport nl14 |
|---|---|---|---|---|---|---|---|---|---|---|---|
| отлаживать | -10,59% | -11,48% | -3,89% | 0,84% | -2,17% | -2,86% | -0,19% | -0,06% | -1,01% | -1,86% | -0,64% |
| след | -62,67% | -60,10% | -67,39% | -36,45% | -9,74% | -11,47% | -10,66% | -6,56% | -14,81% | -14,12% | -7,67% |
| Масштаб набора данных | 120k | 1920k | 500k | 250000k | 217k | 145k | 1705k | 1613k | 18k | 12k | 4k |
| Алгоритм | Позднее принятие | Позднее принятие | Табу Поиск | Табу Поиск | Позднее принятие | Позднее принятие | Табу Поиск | Табу Поиск | Табу Поиск | Табу Поиск | Табу Поиск |
Регистрация трассировки почти в 4 раза медленнее! Влияние ведения журнала отладки намного меньше, но все же заметно во многих случаях. Сценарии использования, использующие Late Acceptance (балансировка облачных вычислений и планирование курса), которые, следовательно, делают больше ведения журнала отладки, по-видимому, имеют более высокую потерю производительности (хотя это может быть в глазах смотрящего).
Но подождите секунду! В этих тестах используется консольный приложение. Что если они используют файловый аппендер, как в производстве?
Регистрация дополнений: добавление в консоль или файл
На рабочем сервере добавление в консоль часто означает потерю информации журнала, когда она попадает в /dev/null . Также во время разработки консольный буфер IDE может переполниться, что приведет к потере строк журнала. Одним из способов избежать этих проблем является настройка файлового приложения. Чтобы сэкономить место на диске, я использовал приложение для добавления файлов, которое сжимает старые файлы журналов в zip-файлы размером 5 МБ:
|
01
02
03
04
05
06
07
08
09
10
11
12
13
14
|
<appender name="appender" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>local/log/optaplanner.log</file> <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy"> <fileNamePattern>local/log/optaplanner.%i.log.zip</fileNamePattern> <minIndex>1</minIndex> <maxIndex>3</maxIndex> </rollingPolicy> <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy"> <maxFileSize>5MB</maxFileSize> </triggeringPolicy> <encoder> <pattern>%d [%t] %-5p %m%n</pattern> </encoder> </appender> |
Это необработанные контрольные цифры, измеренные снова при подсчете среднего значения в секунду (чем выше, тем лучше):
| Регистрация приложений и уровня | Облако 200с | Облако 800с | Машина Б1 | Машина B10 | Курс с7 | Курс с8 | Экзамен S2 | Экзамен S3 | Медсестра М1 | Медсестра mh1 | Sport nl14 |
|---|---|---|---|---|---|---|---|---|---|---|---|
| Информация о консоли | 67393 | 63192 | 123734 | 32461 | 6188 | 8299 | 10330 | 7108 | 3944 | 3654 | 1252 |
| Информация о файле | 66497 | 63065 | 123758 | 33195 | 6302 | 8338 | 10467 | 7238 | 4022 | 3706 | 1256 |
| Консольная отладка | 60254 | 55938 | 118917 | 32735 | 6054 | 8062 | 10310 | 7104 | 3904 | 3586 | 1244 |
| Отладка файла | 55248 | 52261 | 122144 | 31220 | 6223 | 8241 | 10482 | 7118 | 3945 | 3589 | 1238 |
| Трассировка консоли | 25159 | 25214 | 40346 | 20629 | 5585 | 7347 | 9229 | 6642 | 3360 | 3138 | 1156 |
| Трассировка файлов | 10162 | 10708 | 12528 | 9555 | 4416 | 5167 | 6764 | 5532 | 2789 | 2678 | 1101 |
Сколько стоит файл appender по производительности (по сравнению с консольным приложением)?
| Уровень ведения журнала | Облако 200с | Облако 800с | Машина Б1 | Машина B10 | Курс с7 | Курс с8 | Экзамен S2 | Экзамен S3 | Медсестра М1 | Медсестра mh1 | Sport nl14 |
|---|---|---|---|---|---|---|---|---|---|---|---|
| Информация | -1,33% | -0,20% | 0,02% | 2,26% | 1,84% | 0,47% | 1,33% | 1,83% | 1,98% | 1,42% | 0,32% |
| отлаживать | -8,31% | -6,57% | 2,71% | -4,63% | 2,79% | 2,22% | 1,67% | 0,20% | 1,05% | 0,08% | -0,48% |
| след | -59,61% | -57,53% | -68,95% | -53,68% | -20,93% | -29,67% | -26,71% | -16,71% | -16,99% | -14,66% | -4,76% |
Для регистрации информации это не имеет большого значения. Для ведения журнала отладки есть заметное замедление для меньшинства случаев. Регистрация трассировки выполняется почти в 4 раза медленнее! И это соответствует нашему предыдущему наблюдению: в худшем случае (переназначение компьютера B1) регистрация трассировки в файл на 90% медленнее, чем запись информации в консоль.
Вывод
Как и вся диагностическая информация, регистрация ведется за счет снижения производительности. Хорошие библиотеки тщательно выбирают уровень регистрации каждого оператора, чтобы сбалансировать диагностические потребности, многословность и влияние на производительность.
Вот моя рекомендация для пользователей OptaPlanner : В разработке используйте по умолчанию debug (или trace ) с консольным приложением, чтобы вы могли видеть, что происходит. В производстве по умолчанию используйте ведение журнала warn (или info ) с файловым приложением, чтобы сохранить важную информацию.
| Ссылка: | OptaPlanner — Как быстро ведется регистрация? от нашего партнера JCG Джеффри Де Смета в блоге OptaPlanner . |