Поток нити показывает, что нить не снимает блокировку.

Question

• Как показано ниже в дампе потока, поток с идентификатором qtp336276309-556300 получил org.apache.log4j.spi.RootLogger's блокировку и не снял ее.
  Это приводит к блокировке других потоков.
• Это иногда сопровождается тем, что загрузка процессора на хост-компьютере постоянно увеличивается в течение недели с 5% до 30%.
• Хотелось бы знать, могут ли потоки в заблокированном состоянии вызвать скачок ЦП?Если да, то как мне подойти к решению проблемы?
• Если нет, то что еще следует рассмотреть в случае разрешения скачка загрузки ЦП?

• Дамп потока выглядит следующим образом:

  "qtp336276309-561036" #561036 prio=5 os_prio=0 tid=0x00007efe80576800 nid=0x20a7 waiting for monitor entry [0x00007efe19fbd000]
     java.lang.Thread.State: BLOCKED (on object monitor)
      at org.apache.log4j.Category.callAppenders(Category.java:204)
      - waiting to lock <0x00000000e02333c0> (a org.apache.log4j.spi.RootLogger)
      at org.apache.log4j.Category.forcedLog(Category.java:391)
      at org.apache.log4j.Category.log(Category.java:856)
      at org.slf4j.impl.Log4jLoggerAdapter.log(Log4jLoggerAdapter.java:601)
      at org.slf4j.bridge.SLF4JBridgeHandler.callLocationAwareLogger(SLF4JBridgeHandler.java:224)
      at org.slf4j.bridge.SLF4JBridgeHandler.publish(SLF4JBridgeHandler.java:301)
      at java.util.logging.Logger.log(Logger.java:738)
      at java.util.logging.Logger.doLog(Logger.java:765)
      at java.util.logging.Logger.log(Logger.java:788)
      at java.util.logging.Logger.info(Logger.java:1490)
      at org.apache.mesos.chronos.scheduler.api.TaskManagementResource.updateStatus(TaskManagementResource.scala:43)
  
  "qtp336276309-561035" #561035 prio=5 os_prio=0 tid=0x00007efe80193000 nid=0x20a6 waiting for monitor entry [0x00007efe248f4000]
     java.lang.Thread.State: BLOCKED (on object monitor)
      at org.apache.log4j.Category.callAppenders(Category.java:204)
      - waiting to lock <0x00000000e02333c0> (a org.apache.log4j.spi.RootLogger)
      at org.apache.log4j.Category.forcedLog(Category.java:391)
      at org.apache.log4j.Category.info(Category.java:666)
      at mesosphere.chaos.http.ChaosRequestLog.write(ChaosRequestLog.scala:15)
      at org.eclipse.jetty.server.NCSARequestLog.log(NCSARequestLog.java:591)
      at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:92)
      at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:154)
      at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
      at org.eclipse.jetty.server.Server.handle(Server.java:370)
      at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:494)
      at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:971)
      at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1033)
      at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:644)
      at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
      at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
      at org.eclipse.jetty.io.nio.SslConnection.handle(SslConnection.java:196)
      at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:696)
      at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:53)
      at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
      at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
      at java.lang.Thread.run(Thread.java:748)
  
     Locked ownable synchronizers:
      - None
  
  "Thread-328668" #561032 prio=5 os_prio=0 tid=0x00007efe50052000 nid=0x62 waiting for monitor entry [0x00007efe6b0cb000]
     java.lang.Thread.State: BLOCKED (on object monitor)
      at org.apache.log4j.Category.callAppenders(Category.java:204)
      - waiting to lock <0x00000000e02333c0> (a org.apache.log4j.spi.RootLogger)
      at org.apache.log4j.Category.forcedLog(Category.java:391)
      at org.apache.log4j.Category.log(Category.java:856)
      at org.slf4j.impl.Log4jLoggerAdapter.log(Log4jLoggerAdapter.java:601)
      at org.slf4j.bridge.SLF4JBridgeHandler.callLocationAwareLogger(SLF4JBridgeHandler.java:224)
      at org.slf4j.bridge.SLF4JBridgeHandler.publish(SLF4JBridgeHandler.java:301)
      at java.util.logging.Logger.log(Logger.java:738)
      at java.util.logging.Logger.doLog(Logger.java:765)
      at java.util.logging.Logger.log(Logger.java:788)
      at java.util.logging.Logger.info(Logger.java:1490)
      at org.apache.mesos.chronos.scheduler.mesos.MesosJobFramework.statusUpdate(MesosJobFramework.scala:224)
      at sun.reflect.GeneratedMethodAccessor89.invoke(Unknown Source)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      at java.lang.reflect.Method.invoke(Method.java:498)
      at com.google.inject.internal.DelegatingInvocationHandler.invoke(DelegatingInvocationHandler.java:37)
      at com.sun.proxy.$Proxy30.statusUpdate(Unknown Source)
  
     Locked ownable synchronizers:
      - None
  
  
  "qtp336276309-556300" #556300 prio=5 os_prio=0 tid=0x00007efe81654800 nid=0x2047 runnable [0x00007efe1a1c0000]
     java.lang.Thread.State: RUNNABLE
      at java.io.FileOutputStream.writeBytes(Native Method)
      at java.io.FileOutputStream.write(FileOutputStream.java:326)
      at java.io.BufferedOutputStream.write(BufferedOutputStream.java:122)
      - locked <0x00000000e0234470> (a java.io.BufferedOutputStream)
      at java.io.PrintStream.write(PrintStream.java:480)
      - locked <0x00000000e0234450> (a java.io.PrintStream)
      at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
      at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
      at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:295)
      at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)
      - locked <0x00000000e0234438> (a java.io.OutputStreamWriter)
      at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)
      at org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:59)
      at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:324)
      at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
      at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
      - locked <0x00000000e0233cc0> (a org.apache.log4j.ConsoleAppender)
      at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
      at org.apache.log4j.Category.callAppenders(Category.java:206)
      - locked <0x00000000e02333c0> (a org.apache.log4j.spi.RootLogger)
      at org.apache.log4j.Category.forcedLog(Category.java:391)
      at org.apache.log4j.Category.info(Category.java:666)
      at mesosphere.chaos.http.ChaosRequestLog.write(ChaosRequestLog.scala:15)
      at org.eclipse.jetty.server.NCSARequestLog.log(NCSARequestLog.java:591)
      at org.eclipse.jetty.server.handler.RequestLogHandler.handle(RequestLogHandler.java:92)
      at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:154)
      at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
      at org.eclipse.jetty.server.Server.handle(Server.java:370)
      at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:494)
      at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:971)
      at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1033)
      at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:644)
      at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
      at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
      at org.eclipse.jetty.io.nio.SslConnection.handle(SslConnection.java:196)
      at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:696)
      at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:53)
      at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
      at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
      at java.lang.Thread.run(Thread.java:748)
  
     Locked ownable synchronizers:
      - None
  

Answer 1

Как показано ниже в дампе потока, поток с идентификатором qtp336276309-556300 получил блокировку org.apache.log4j.spi.RootLogger и не снял ее.Это приводит к блокировке других потоков.

Это нормально, только один поток может одновременно регистрироваться в файле.Если у вас есть несколько потоков, пытающихся писать одновременно, они должны ждать.

Это иногда сопровождается тем, что загрузка ЦП на хосте постоянно увеличивается в течение недели с 5% до 30%.

Хотя ведение журнала является очень распространенной причиной замедления, со временем оно обычно не ухудшается.

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

Хотелось бы узнать, могут ли потоки в заблокированном состоянии вызывать скачок ЦП?

ЗАБЛОКИРОВАННЫЕ потоки не сильно загружают ЦП.Хотя это может привести к более высоким задержкам, вы можете не увидеть какого-либо увеличения загрузки ЦП (на самом деле оно может снизиться)

Если нет, то что еще следует рассмотреть в случае разрешения скачка загрузки ЦП?

Я бы посмотрел, что другие потоки делают в это время.Я бы попытался уменьшить количество журналов, чтобы уменьшить количество «шума», чтобы вы могли видеть, что он делает большую часть времени.