Регистратор зависает во время logger.info - PullRequest
0 голосов
/ 02 октября 2019

Моя фоновая работа (регулярно) застревает при вызове log.info (...) с Logback:

"pool-5-thread-1" #30 prio=5 os_prio=0 tid=0x00007f11c4ff2000 nid=0x100 waiting on condition [0x00007f11bd21a000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000db93e3a8> (a java.util.concurrent.locks.ReentrantLock$FairSync)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
    at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:224)
    at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
    at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:217)
    at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103)
    at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)
    at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
    at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:273)
    at ch.qos.logback.classic.Logger.callAppenders(Logger.java:260)
    at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:442)
    at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396)
    at ch.qos.logback.classic.Logger.info(Logger.java:600)
    at com.website.configuration.BackgroundJobs.lambda$run$2(BackgroundJobs.java:410)
    at com.website.configuration.BackgroundJobs$$Lambda$85/1402118067.accept(Unknown Source)
    at java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
    at java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:647)
    at com.website.configuration.BackgroundJobs.run(BackgroundJobs.java:396)
    at sun.reflect.GeneratedMethodAccessor59.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
    at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

Он находится в этом состоянии и не прогрессирует, пока я не перезапущу сервер.

Есть идеи, почему это может произойти?

Я использую весеннюю загрузку 1.3.1.RELEASE с org.springframework.boot: spring-boot-starter-web: 1.3.1.RELEASEкоторый использует logback-classic-1.1.3.

И я определяю свои регистраторы в моих классах @Controllers и @Configuration следующим образом:

final Logger log = LoggerFactory.getLogger(getClass().getName());

А вот еще один дамп потокапоказывает ту же проблему, но на этот раз log.info вызывается из другого класса:

"pool-5-thread-1" #30 prio=5 os_prio=0 tid=0x00007f96f5cdc800 nid=0x100 waiting on condition [0x00007f9737d66000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000db6501f0> (a java.util.concurrent.locks.ReentrantLock$FairSync)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
    at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:224)
    at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
    at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:217)
    at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:103)
    at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88)
    at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
    at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:273)
    at ch.qos.logback.classic.Logger.callAppenders(Logger.java:260)
    at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:442)
    at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:396)
    at ch.qos.logback.classic.Logger.info(Logger.java:600)
    at com.website.service.JobScheduler.scheduleJob(JobScheduler.java:55)
    at com.website.configuration.BackgroundJobs.lambda$run$2(BackgroundJobs.java:411)
    at com.website.configuration.BackgroundJobs$$Lambda$85/1061458720.accept(Unknown Source)
    at java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
    at java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:647)
    at com.website.configuration.BackgroundJobs.run(BackgroundJobs.java:396)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
    at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

1 Ответ

0 голосов
/ 02 октября 2019

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

Улучшили ситуацию, уменьшив количествоведения журналов, которые я делаю.

, а позже рассмотрим библиотеки асинхронного ведения журналов (т. е. не блокирующие регистраторы).

...