Log4j2 Блокировка потоков в OutputStreamManager.write - PullRequest
0 голосов
/ 05 мая 2020

Фон Я использую log4j2 (2.12.1) с Syn c root и Asyn c logger. Размер кольцевого буфера Lmax по умолчанию равен 256 * 1024. Мой аппендер в консоли. Я регистрирую MapMessage с макетом JSON. Средний размер моего сообщения журнала составляет около 100 байт.

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

"http-nio-8080-exec-172" #451
   Thread State: BLOCKED (on object monitor) owned by "http-nio-8080-exec-148" Id=429
  at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:231)
  - blocked on <0x000000003eb936ae> (a org.apache.logging.log4j.core.appender.OutputStreamManager)
  at org.apache.logging.log4j.core.appender.OutputStreamManager.writeBytes(OutputStreamManager.java:206)
  at org.apache.logging.log4j.core.layout.AbstractLayout.encode(AbstractLayout.java:211)
  at org.apache.logging.log4j.core.layout.AbstractLayout.encode(AbstractLayout.java:37)
  at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:197)
  at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:190)
  at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:181)
  at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
  at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
  at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
  at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
  at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:543)
  at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:502)
  at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:485)
  at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:534)
  at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:504)
  at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:485)
  at org.apache.logging.log4j.core.async.AsyncLoggerConfig.log(AsyncLoggerConfig.java:121)
  at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:460)
  at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:82)
  at org.apache.logging.log4j.core.Logger.log(Logger.java:162)
  at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2190)
  at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2144)
  at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2127)
  at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1828)
  at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1282)

Мой вопрос:

  1. Кольцевой буфер заполняется очень быстро, что вызывает обратное давление на основной поток (в моем случае поток контейнера сервлета, который является http-nio-8080-exe c -148)? Дамп кучи показывает, что RingBuffer всегда занимал 7 МБ (до и после теста).
  2. Если кольцевой буфер заполняется очень быстро, как я могу увеличить его размер? или могут быть события сброса ??
  3. Глядя на отчет о производительности Log42, я знаю, что консольное приложение не предлагается, но у меня действительно нет выбора. Есть ли здесь лучший аппендер, который пишет в STDOUT?

Приветствуются любые предложения или мысли.

1 Ответ

1 голос
/ 05 мая 2020

Эта блокировка предназначена для предотвращения одновременной записи нескольких потоков в один и тот же OutputStream, поскольку это может привести к смешению данных. Хотя это не гарантируется, многие реализации OutputStream в любом случае блокируют вызовы на запись - поэтому даже если бы блокировка была снята, она просто заблокировалась бы в реализации OutputStream.

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

Обновление : После просмотра полного дампа потока у меня есть некоторые наблюдения:

  1. Есть много потоков, ожидающих в com.xxxx.apie.library.InternalRequest.execute(InternalRequest.java:273). Похоже, они ожидают выполнения работы в другом потоке, но из дампа потока неясно, что именно.
  2. Есть несколько потоков, записывающихся в выходной поток, которые заблокированы. Вызовы исходят из разных точек в паре классов, но все они регистрируются на информационном уровне.
  3. Вы используете JsonLayout.
  4. Вы не разместили свою конфигурацию Log4j, но в трассировке стека выше вы можете видеть, что AsyncLoggerConfig вызывает метод журнала LoggerConfig. При просмотре кода в AsyncLogger может показаться, что вы настроили AsyncLogger, у которого нет ссылок на приложение, поэтому регистратор делегирует свои полномочия своему родителю, который НЕ является асинхронным регистратором, поэтому событие журнала даже не помещается в очередь в кольцевой буфер, а регистрируется непосредственно из потока приложения.

Суть в том, что вы ведете журнал синхронно в OutputStream (возможно, в консоль), и потоки блокируют это, потому что ввод-вывод медленный.

Добро пожаловать на сайт PullRequest, где вы можете задавать вопросы и получать ответы от других членов сообщества.
...