Plumbr был известен как инструмент для устранения утечек памяти. Всего два месяца назад мы выпустили функции оптимизации GC . Но после этого мы не сидели без дела — в течение многих месяцев мы работали над обнаружением конфликтов блокировки.
В ходе тестов мы обнаружили много неуклюжих проблем параллелизма в сотнях различных приложений. Многие из этих проблем являются уникальными для рассматриваемого приложения, но выделяется один конкретный тип проблем.
Мы обнаружили, что почти каждое Java-приложение использует Log4j или Logback. На самом деле, исходя из имеющихся у нас данных, кажется, что более 90% приложений используют любую из этих платформ для ведения журнала. Но это не самая интересная часть. Интересно, что около трети из этих приложений сталкиваются с довольно значительным временем ожидания блокировки во время регистрации вызовов. В настоящее время более 10% приложений Java, по-видимому, время от времени останавливаются более чем на 5000 миллисекунд во время невинно выглядящего вызова log.debug () .
Почему так? Выбор приложения по умолчанию для любой серверной среды — это своего рода приложение File, например, RollingFileAppender. Важно то, что эти приложения синхронизированы. Это простой способ гарантировать, что последовательность записей журнала из разных потоков сохраняется.
Чтобы продемонстрировать побочные эффекты для этого подхода, мы настроили простой тест JMH (MyBenchmark), который ничего не делает, кроме вызова log.debug (). Этот тест проводился на четырехъядерном MacBook Pro с 1,2 и 50 потоками. Было выбрано 50 потоков для имитации типичной настройки приложения сервлета с 50 рабочими потоками HTTP.
|
01
02
03
04
05
06
07
08
09
10
11
12
13
14
15
16
17
18
19
20
21
22
|
@State(Scope.Benchmark)public class LogBenchmark { static final Logger log = LoggerFactory.getLogger(LogBenchmark.class); AtomicLong counter; @Benchmark public void testMethod() { log.debug(String.valueOf(counter.incrementAndGet())); } @Setup public void setup() { counter = new AtomicLong(0); } @TearDown public void printState() { System.out.println("Expected number of logging lines in debug.log: " + counter.get()); }} |
Из результатов теста мы видим резкое снижение пропускной способности на 278 898 операций / с -> 84 630 операций / с -> 73 789 операций / с. Мы видим, что при пропускной способности системы от 1 до 2 потоков уменьшается в 3,3 раза .
Так как же избежать подобных проблем с блокировками? Решение простое — более десяти лет в каркасах логирования присутствовал аппендиат AsyncAppender . Идея этого приложения заключается в том, чтобы сохранить сообщение журнала в очереди и вернуть поток обратно в приложение. Таким образом, платформа может асинхронно хранить сообщение журнала в отдельном потоке.
Посмотрим, как AsyncAppender может справиться с многопоточным приложением. Мы настроили аналогичный простой тест, но настроили регистратор для этого класса для использования AsyncAppender. Теперь, когда мы запускаем тест с теми же потоками 1, 2 и 50, мы получаем ошеломляющие результаты: 4,941,874 операций / с -> 6,608,732 операций / с -> 5,517,848 операций / с. Улучшение пропускной способности настолько хорошее, что вызывает подозрение, что происходит что-то подозрительное.
Давайте посмотрим на документацию AsyncAppender . В нем говорится, что AsyncAppender по умолчанию является регистратором с потерями, что означает, что, когда очередь регистратора заполнится, appender начнет отбрасывать сообщения трассировки, отладки и информационного уровня, так что предупреждения и ошибки обязательно будут записаны. Это поведение настраивается с использованием 2 параметров — discardingThreshold и queueSize. Первый указывает, насколько полной должна быть очередь, когда сообщения начнут отбрасываться, второй, очевидно, указывает, насколько велика очередь.
Размер очереди по умолчанию, заданный равным 256, может, например, быть настроен на 0, чтобы вообще отключить сброс, так что аппендер блокируется, когда очередь заполнится. Чтобы лучше понять результаты, давайте посчитаем ожидаемое количество сообщений в файле журнала (поскольку количество вызовов эталонных тестов JMH не является детерминированным), а затем сравним, сколько фактически было написано, чтобы увидеть, сколько сообщений на самом деле отбрасывается, чтобы получить такая блестящая пропускная способность.
Мы запустили тест с 50 потоками, изменили размер очереди и включили и выключили отбрасывание. Результаты приведены ниже:
| Размер очереди | Выбросьте | Не выбрасывать | |||
| OPS / s | Ожидаемое сообщение | Фактическое сообщение | Потерял сообщение | OPS / s | |
| 256 | 4180312 | 184248790 | 1925829 | 98,95% | 118340 |
| +4096 | 4104997 | 182404138 | 694902 | 99,62% | 113534 |
| 65536 | 3558543 | 157385651 | 1762404 | 98,88% | 137583 |
| 1048576 | 3213489 | 141409403 | 1560612 | 98,90% | 117820 |
| 2000000 | 3306476 | 141454871 | 1527133 | 98,92% | 108603 |
Что мы можем из них сделать вывод? Там нет бесплатных обедов и нет магии. Либо мы отбрасываем 98% сообщений журнала, чтобы получить такой значительный выигрыш в пропускной способности, либо, когда очередь заполняется, мы начинаем блокировать и возвращаемся к производительности, сравнимой с синхронным приложением. Интересно, что размер очереди не сильно влияет. В случае, если вы можете пожертвовать журналами отладки, использование AsyncAppender имеет смысл.
| Ссылка: | Блокировка и регистрация от нашего партнера JCG Владимира Сора в блоге Plumbr Blog . |