CODEWITHSUNDEEP
scalaakkacodahale-metrics
smeeb
smeeb

Reputation: 29567

Scala/Akka/Dropwizard Metrics app hanging for 10s before shutting down

I have a Scala 2.11 app that uses Akka. The GitHub repo for it is here. To reproduce what I'm seeing, just clone it, build it via ./gradlew fullBuild and then run it via java -jar build/libs/akka-scala-troubleshooting.jar (its a self-contained executable JAR). But essentially, I'm noticing that when I kill the running JVM process via Ctrl+C that it takes exactly 10 seconds for the JAR to shut down!

IIRC, Ctrl+C should issue a SIGKILL to the JVM process, so how it lives for another 10 seconds thereafter is blowing my mind! Even if I'm recalling that incorrectly, I'd still like to know why my app isn't shutting down immediately (it's causing problems by not doing so).

I'm using Dropwizard (formerly Coda Hale) Metrics via the Scala Metrics library. From what I can tell there might be a scheduled reporter daemon still alive that isn't shutting down right away, even when the JVM receives the SIGKILL (or whatever Ctrl+C is sending). Here's the main Driver (app entry point):

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...")
}

When you run the JAR, you'll see this output to the logs:

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!

At this point it will just idle and do nothing -- that's fine and intended! But when I hit Ctrl+C on the terminal, I immediately get this log INFO:

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

Then 10 seconds goes by (exactly 10s every time), then finally a log WARNing:

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

Any idea what could be going on here?

Update:

I did a thread dump:

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

Note that 2 threads are trying to call Shutdown.exit...

Upvotes: 0

Views: 722

Answers (1)

Jeffrey Chung
Jeffrey Chung

Reputation: 19527

The 10 seconds is defined here in the configuration:

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

When system.terminate() is called, CoordinatedShutdown by default is initiated. Notice that this method returns a Future, meaning that termination will happen asynchronously. By default, there is a 10-second timeout for the actor system to shut down.

In your driver, you call registerOnTermination. The Scaladoc for this method states:

Note that ActorSystem will not terminate until all the registered callbacks are finished.

Your registered callback invokes System.exit, and you're getting the timeout warning because the actor system is unable to properly shut down within the 10-second window. The System.exit call is probably interfering with the actor system's coordinated shutdown. Removing the System.exit call in registerOnTermination, or removing the call to registerOnTermination altogether, will remove the warning.

Upvotes: 3

Related Questions