Приложение Scala/Akka/Dropwizard Metrics зависает на 10 секунд перед тем, как завершить работу

Question

Приложение Scala/Akka/Dropwizard Metrics зависает на 10 секунд перед тем, как завершить работу

У меня есть приложение Scala 2.11, которое использует Akka. Репозиторий GitHub для этого здесь. Чтобы воспроизвести то, что я вижу, просто клонируйте его, создайте через ./gradlew fullBuild а затем запустить его через java -jar build/libs/akka-scala-troubleshooting.jar (это автономный исполняемый файл JAR). Но по сути, я замечаю, что когда я убиваю запущенный процесс JVM через Ctrl+C что для отключения JAR требуется ровно 10 секунд!

IIRC, Ctrl+C Я должен выпустить SIGKILL для процесса JVM, так что то, как он живет еще 10 секунд после этого, поражает меня! Даже если я вспоминаю это неправильно, я все равно хотел бы знать, почему мое приложение не закрывается немедленно (это вызывает проблемы, если я этого не делаю).

Я использую Метрики Dropwizard (ранее Coda Hale) через библиотеку Scala Metrics. Из того, что я могу сказать, может быть запланированный демон репортера, который еще жив, который не выключается сразу, даже когда JVM получает SIGKILL (или что-то еще Ctrl+C отправляет). Вот основной драйвер (точка входа в приложение):

object Driver extends App {
  println("Starting upp the app...")
  //SLF4JBridgeHandler.install()
  lazy val metricRegistry = new MetricRegistry()
  ConsoleReporter
    .forRegistry(metricRegistry)
    .convertRatesTo(TimeUnit.SECONDS)
    .convertDurationsTo(TimeUnit.MILLISECONDS)
    .build()
    .start(15, TimeUnit.SECONDS)

  lazy val cortex = ActorSystem("cortex")
  cortex.registerOnTermination {
    System.exit(0)
  }

  val master = cortex.actorOf(Props[Master], name = "Master")

  println("About to fire a StartUp message at Master...")
  master ! StartUp
  println("Fired! Actor system is spinning up...")
}

Когда вы запустите JAR, вы увидите этот вывод в журналах:

java -jar build/libs/akka-scala-troubleshooting.jar 
Starting upp the app...
About to fire a StartUp message at Master...
Fired! Actor system is spinning up...
Master has received a command to start up the actor system!
Child will make it happen!

В этот момент он просто простаивает и ничего не делает - это нормально и предназначено! Но когда я ударил Ctrl+C на терминале я сразу получаю этот лог ИНФО:

^C[INFO] [08/03/2017 06:15:57.236] [Thread-0] [CoordinatedShutdown(akka://cortex)] Starting coordinated shutdown from JVM shutdown hook

Затем проходит 10 секунд (ровно 10 секунд каждый раз), затем, наконец, журнал ПРЕДУПРЕЖДЕНИЕ:

[WARN] [08/03/2017 06:16:07.248] [Thread-0] [CoordinatedShutdown(akka://cortex)] CoordinatedShutdown from JVM shutdown failed: Futures timed out after [10000 milliseconds]

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

Обновить:

Я сделал дамп потока:

2017-08-03 14:08:58
Full thread dump OpenJDK 64-Bit Server VM (25.131-b11 mixed mode):

"cortex-akka.actor.default-dispatcher-5" #19 prio=5 os_prio=0 tid=0x00007fcba8009000 nid=0x547d waiting on condition [0x00007fcc16e6f000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x000000076ff34e28> (a akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinPool)
    at akka.dispatch.forkjoin.ForkJoinPool.scan(ForkJoinPool.java:2075)
    at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
    at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)

   Locked ownable synchronizers:
    - None

"Thread-0" #15 prio=5 os_prio=0 tid=0x00007fcba0001000 nid=0x547c waiting on condition [0x00007fcc17170000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x0000000770b33920> (a scala.concurrent.impl.Promise$CompletionLatch)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
    at scala.concurrent.impl.Promise$DefaultPromise.tryAwait(Promise.scala:212)
    at scala.concurrent.impl.Promise$DefaultPromise.ready(Promise.scala:222)
    at scala.concurrent.impl.Promise$DefaultPromise.ready(Promise.scala:157)
    at scala.concurrent.Await$$anonfun$ready$1.apply(package.scala:169)
    at scala.concurrent.Await$$anonfun$ready$1.apply(package.scala:169)
    at scala.concurrent.BlockContext$DefaultBlockContext$.blockOn(BlockContext.scala:53)
    at scala.concurrent.Await$.ready(package.scala:169)
    at akka.actor.CoordinatedShutdown$$anonfun$initJvmHook$1.apply(CoordinatedShutdown.scala:161)
    at akka.actor.CoordinatedShutdown$$anon$2.run(CoordinatedShutdown.scala:446)

   Locked ownable synchronizers:
    - None

"SIGTERM handler" #18 daemon prio=9 os_prio=0 tid=0x00007fcbdc002800 nid=0x547b in Object.wait() [0x00007fcc17271000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000007707bb150> (a akka.actor.CoordinatedShutdown$$anon$2)
    at java.lang.Thread.join(Thread.java:1252)
    - locked <0x00000007707bb150> (a akka.actor.CoordinatedShutdown$$anon$2)
    at java.lang.Thread.join(Thread.java:1326)
    at java.lang.ApplicationShutdownHooks.runHooks(ApplicationShutdownHooks.java:106)
    at java.lang.ApplicationShutdownHooks$1.run(ApplicationShutdownHooks.java:46)
    at java.lang.Shutdown.runHooks(Shutdown.java:123)
    at java.lang.Shutdown.sequence(Shutdown.java:167)
    at java.lang.Shutdown.exit(Shutdown.java:212)
    - locked <0x00000007707bb5d0> (a java.lang.Class for java.lang.Shutdown)
    at java.lang.Terminator$1.handle(Terminator.java:52)
    at sun.misc.Signal$1.run(Signal.java:212)
    at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
    - None

"Attach Listener" #17 daemon prio=9 os_prio=0 tid=0x00007fcbdc001000 nid=0x545f waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"DestroyJavaVM" #16 prio=5 os_prio=0 tid=0x00007fcc3800c000 nid=0x5427 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"cortex-akka.actor.default-dispatcher-4" #14 prio=5 os_prio=0 tid=0x00007fcbb0010000 nid=0x5445 waiting for monitor entry [0x00007fcc17473000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at java.lang.Shutdown.exit(Shutdown.java:212)
    - waiting to lock <0x00000007707bb5d0> (a java.lang.Class for java.lang.Shutdown)
    at java.lang.Runtime.exit(Runtime.java:109)
    at java.lang.System.exit(System.java:971)
    at hotmeatballsoup.Driver$$anonfun$1.apply$mcV$sp(Driver.scala:24)
    at hotmeatballsoup.Driver$$anonfun$1.apply(Driver.scala:24)
    at hotmeatballsoup.Driver$$anonfun$1.apply(Driver.scala:24)
    at akka.actor.ActorSystemImpl$$anon$3.run(ActorSystem.scala:810)
    at akka.actor.ActorSystemImpl$TerminationCallbacks$$anonfun$addRec$1$1.applyOrElse(ActorSystem.scala:987)
    at akka.actor.ActorSystemImpl$TerminationCallbacks$$anonfun$addRec$1$1.applyOrElse(ActorSystem.scala:987)
    at scala.concurrent.Future$$anonfun$andThen$1.apply(Future.scala:436)
    at scala.concurrent.Future$$anonfun$andThen$1.apply(Future.scala:435)
    at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:36)
    at akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:55)
    at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run$1.apply$mcV$sp(BatchingExecutor.scala:91)
    at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run$1.apply(BatchingExecutor.scala:91)
    at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run$1.apply(BatchingExecutor.scala:91)
    at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:72)
    at akka.dispatch.BatchingExecutor$BlockableBatch.run(BatchingExecutor.scala:90)
    at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:38)
    at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(ForkJoinExecutorConfigurator.scala:43)
    at akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
    at akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
    at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
    at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)

   Locked ownable synchronizers:
    - None

"cortex-akka.actor.default-dispatcher-3" #13 prio=5 os_prio=0 tid=0x00007fcc386e8800 nid=0x5444 waiting on condition [0x00007fcc17574000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x000000076ff34e28> (a akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinPool)
    at akka.dispatch.forkjoin.ForkJoinPool.scan(ForkJoinPool.java:2075)
    at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
    at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)

   Locked ownable synchronizers:
    - None

"cortex-akka.actor.default-dispatcher-2" #12 prio=5 os_prio=0 tid=0x00007fcc386db000 nid=0x5443 waiting on condition [0x00007fcc17675000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x000000076ff34e28> (a akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinPool)
    at akka.dispatch.forkjoin.ForkJoinPool.scan(ForkJoinPool.java:2075)
    at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
    at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)

   Locked ownable synchronizers:
    - None

"cortex-scheduler-1" #11 prio=5 os_prio=0 tid=0x00007fcc38645800 nid=0x5442 waiting on condition [0x00007fcc17976000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at akka.actor.LightArrayRevolverScheduler.waitNanos(LightArrayRevolverScheduler.scala:85)
    at akka.actor.LightArrayRevolverScheduler$$anon$4.nextTick(LightArrayRevolverScheduler.scala:265)
    at akka.actor.LightArrayRevolverScheduler$$anon$4.run(LightArrayRevolverScheduler.scala:235)
    at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
    - None

"metrics-console-reporter-1-thread-1" #10 daemon prio=5 os_prio=0 tid=0x00007fcc384ee800 nid=0x5441 waiting on condition [0x00007fcc17c77000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x000000076e328370> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
    - None

Обратите внимание, что 2 темы пытаются позвонить Shutdown.exit...

0

scala akka codahale-metrics

Источник

user4009451 03 авг '17 в 10:22

1 ответ

Другие вопросы по тегам scala akka codahale-metrics

user865401 03 авг '17 в 11:33 2017-08-03 11:33 · Answer 1 · 2017-08-03 11:33

10 секунд определены здесь в конфигурации:

actor-system-terminate {
  timeout = 10 s
  depends-on = [before-actor-system-terminate]
}

когда system.terminate() называется, CoordinatedShutdown по умолчанию инициируется. Обратите внимание, что этот метод возвращает Future Это означает, что завершение будет происходить асинхронно. По умолчанию для актерской системы требуется 10-секундный тайм-аут.

В вашем водителе вы звоните registerOnTermination, Скаладок для этого метода гласит:

Обратите внимание, что ActorSystem не завершится, пока не будут завершены все зарегистрированные обратные вызовы.

Ваш зарегистрированный обратный вызов вызывает System.exit, и вы получаете предупреждение о тайм-ауте, потому что система актера не может правильно завершить работу в пределах 10-секундного окна. System.exit вызов, вероятно, вмешивается в скоординированное отключение системы актера. Удаление System.exit вызывать registerOnTermination или удаление звонка registerOnTermination в общем, уберу предупреждение.