You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@samza.apache.org by "Abhishek Shivanna (Jira)" <ji...@apache.org> on 2019/09/11 22:42:00 UTC
[jira] [Commented] (SAMZA-2198) Container process always takes
task.shutdown.ms to shut down
[ https://issues.apache.org/jira/browse/SAMZA-2198?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16928066#comment-16928066 ]
Abhishek Shivanna commented on SAMZA-2198:
------------------------------------------
We remove the shutdown hook as part of the container shutdown sequence with `removeShutdownHook` in `SamzaContainer.scala` - if we gracefully got to LocalContainerRunner the shutdown hook will no longer run on exit.
This is most likely caused due to a signal (possibly SIGTERM) sent to the container. Since the hook isn't removed in this case, it causes the deadlock.
The following is the log when a signal (kill -15 PID) is sent to the container - Similar to what is stated in the comments above:
{noformat}
2019-09-11 15:12:33.119 [Thread-2] WikipediaFeed [INFO] Reply #366: samza-bot-1491675736 #en.wikipedia End of /NAMES list.
2019-09-11 15:12:33.236 [kafka-producer-network-thread | kafka_producer-wikipedia_application-1] Metadata [INFO] Cluster ID: eMZ2zWSCREGFD-huGjEQZw
2019-09-11 15:13:21.058 [Thread-2] WikipediaFeed [INFO] #en.wikipedia> flink-bot-aa6ef14c-188c-4eb8-89d6-0c2c30ed844f joins
2019-09-11 15:13:22.269 [main] KafkaSystemAdmin [INFO] Fetching SSP metadata for: [SystemStreamPartition [kafka, wikipedia-application-1-window-statsWindow, 0], SystemStreamPartition [kafka, wikipedia-stats-changelog, 0]]
2019-09-11 15:14:02.321 [Samza Container Shutdown Hook Thread] SamzaContainer [INFO] Shutting down, will wait up to 30000 ms.
2019-09-11 15:14:02.322 [main] SamzaContainer [INFO] Shutting down SamzaContainer.
2019-09-11 15:14:02.325 [main] SamzaContainer [INFO] Shutting down consumer multiplexer.
2019-09-11 15:14:02.360 [main] SamzaContainer [INFO] Shutting down task instance stream tasks.
2019-09-11 15:14:02.360 [main] SamzaContainer [INFO] Shutting down timer executor
2019-09-11 15:14:02.364 [main] SamzaContainer [INFO] Shutting down task instance table manager.
2019-09-11 15:14:02.365 [main] SamzaContainer [INFO] Shutting down container storage manager.
2019-09-11 15:14:02.370 [main] ContainerStorageManager [INFO] Shutdown complete
2019-09-11 15:14:02.370 [main] SamzaContainer [INFO] Shutting down host statistics monitor.
2019-09-11 15:14:02.371 [main] SamzaContainer [INFO] Shutting down producer multiplexer.
2019-09-11 15:14:02.372 [main] KafkaSystemProducer [INFO] Stopping producer for system: kafka
2019-09-11 15:14:02.372 [main] KafkaProducer [INFO] [Producer clientId=kafka_producer-wikipedia_application-1] Closing the Kafka producer with timeoutMillis = 9223372036854775807 ms.
2019-09-11 15:14:02.374 [main] SamzaContainer [INFO] Shutting down offset manager.
2019-09-11 15:14:02.375 [main] StartpointManager [WARN] already stopped
2019-09-11 15:14:02.375 [main] SamzaContainer [INFO] Shutting down metrics reporters.
2019-09-11 15:14:02.376 [main] MetricsSnapshotReporter [INFO] Stopping reporter timer.
2019-09-11 15:14:02.388 [main] MetricsSnapshotReporter [INFO] Stopping producer.
2019-09-11 15:14:02.388 [main] KafkaSystemProducer [INFO] Stopping producer for system: kafka
2019-09-11 15:14:02.388 [main] KafkaProducer [INFO] [Producer clientId=kafka_producer-wikipedia_application-1] Closing the Kafka producer with timeoutMillis = 9223372036854775807 ms.
2019-09-11 15:14:02.389 [main] SamzaContainer [INFO] Shutting down JVM metrics.
2019-09-11 15:14:02.389 [main] SamzaContainer [INFO] Shutting down admin multiplexer.
2019-09-11 15:14:02.392 [main] SamzaContainer [INFO] Shutdown complete.
2019-09-11 15:14:02.392 [main] ContainerLaunchUtil [INFO] Container Stopped
2019-09-11 15:14:02.392 [main] ContainerHeartbeatMonitor [INFO] Stopping ContainerHeartbeatMonitor
2019-09-11 15:14:02.392 [main] CoordinatorStreamStore [INFO] Stopping the coordinator stream system consumer.
2019-09-11 15:14:02.393 [main] KafkaSystemProducer [INFO] Stopping producer for system: kafka
2019-09-11 15:14:02.393 [main] KafkaProducer [INFO] [Producer clientId=kafka_producer-wikipedia_application-1] Closing the Kafka producer with timeoutMillis = 9223372036854775807 ms.
2019-09-11 15:14:02.394 [main] KafkaSystemConsumer [INFO] kafka:kafka_consumer-wikipedia_application-1: Stopping Samza kafkaConsumer
2019-09-11 15:14:02.394 [main] KafkaSystemConsumer [INFO] kafka:kafka_consumer-wikipedia_application-1: Stopping proxy consumerProxy-kafka-kafka_consumer-wikipedia_application-1
2019-09-11 15:14:02.394 [main] KafkaConsumerProxy [INFO] Shutting down KafkaConsumerProxy poll thread Samza KafkaConsumerProxy Poll Thread-1 - kafka for consumerProxy-kafka-kafka_consumer-wikipedia_application-1
2019-09-11 15:14:02.702 [Samza KafkaConsumerProxy Poll Thread-1 - kafka] KafkaConsumerProxy [INFO] KafkaConsumerProxy for system kafka has stopped.
2019-09-11 15:14:02.702 [main] KafkaSystemConsumer [INFO] kafka:kafka_consumer-wikipedia_application-1: Closing kafkaSystemConsumer org.apache.kafka.clients.consumer.KafkaConsumer@5717c37
2019-09-11 15:14:32.325 [Samza Container Shutdown Hook Thread] SamzaContainer [ERROR] Did not shut down within 30000 ms, exiting.
2019-09-11 15:14:32.334 [Samza Container Shutdown Hook Thread] ThreadUtil [INFO] Thread dump from Samza Container Shutdown Hook.
"RMI TCP Connection(idle)" Id=38 TIMED_WAITING on java.util.concurrent.SynchronousQueue$TransferStack@ee0730
at sun.misc.Unsafe.park(Native Method)
- waiting on java.util.concurrent.SynchronousQueue$TransferStack@ee0730
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
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)
"Samza Container Shutdown Hook Thread" Id=33 RUNNABLE
at sun.management.ThreadImpl.dumpThreads0(Native Method)
at sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:454)
at org.apache.samza.util.ThreadUtil.logThreadDump(ThreadUtil.java:35)
at org.apache.samza.container.SamzaContainer$$anon$1.run(SamzaContainer.scala:995)
"SIGTERM handler" Id=37 WAITING on org.apache.samza.container.SamzaContainer$$anon$1@18151a14
at java.lang.Object.wait(Native Method)
- waiting on org.apache.samza.container.SamzaContainer$$anon$1@18151a14
at java.lang.Thread.join(Thread.java:1252)
at java.lang.Thread.join(Thread.java:1326)
at java.lang.ApplicationShutdownHooks.runHooks(ApplicationShutdownHooks.java:107)
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 java.lang.Class@32107a7d
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)
"RMI RenewClean-[ashivann-mn2.linkedin.biz:63403]" Id=25 TIMED_WAITING on java.lang.ref.ReferenceQueue$Lock@45d9b29c
at java.lang.Object.wait(Native Method)
- waiting on java.lang.ref.ReferenceQueue$Lock@45d9b29c
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run(DGCClient.java:563)
at java.lang.Thread.run(Thread.java:748)
"RMI Scheduler(0)" Id=24 TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@726b4775
at sun.misc.Unsafe.park(Native Method)
- waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@726b4775
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)
"GC Daemon" Id=22 TIMED_WAITING on sun.misc.GC$LatencyLock@118d99ae
at java.lang.Object.wait(Native Method)
- waiting on sun.misc.GC$LatencyLock@118d99ae
at sun.misc.GC$Daemon.run(GC.java:117)
"RMI TCP Accept-0" Id=19 RUNNABLE (in native)
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
at java.net.ServerSocket.implAccept(ServerSocket.java:545)
at java.net.ServerSocket.accept(ServerSocket.java:513)
at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:405)
at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:377)
at java.lang.Thread.run(Thread.java:748)
"Signal Dispatcher" Id=4 RUNNABLE
"Finalizer" Id=3 WAITING on java.lang.ref.ReferenceQueue$Lock@7625d9a7
at java.lang.Object.wait(Native Method)
- waiting on java.lang.ref.ReferenceQueue$Lock@7625d9a7
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)
"Reference Handler" Id=2 WAITING on java.lang.ref.Reference$Lock@b987e24
at java.lang.Object.wait(Native Method)
- waiting on java.lang.ref.Reference$Lock@b987e24
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
"main" Id=1 BLOCKED on java.lang.Class@32107a7d owned by "SIGTERM handler" Id=37
at java.lang.Shutdown.exit(Shutdown.java:212)
- blocked on java.lang.Class@32107a7d
at java.lang.Runtime.exit(Runtime.java:109)
at java.lang.System.exit(System.java:971)
at org.apache.samza.runtime.ContainerLaunchUtil.run(ContainerLaunchUtil.java:85)
at org.apache.samza.runtime.LocalContainerRunner.main(LocalContainerRunner.java:80){noformat}
The following are the logs seen with the changes applied in the pull request:
{noformat}
With the fix:
2019-09-11 15:32:24.097 [Thread-2] WikipediaFeed [INFO] Reply #366: samza-bot-404062277 #en.wikipedia End of /NAMES list.
2019-09-11 15:32:24.450 [kafka-producer-network-thread | kafka_producer-wikipedia_application-1] Metadata [INFO] Cluster ID: eMZ2zWSCREGFD-huGjEQZw
2019-09-11 15:32:30.107 [Thread-2] WikipediaFeed [INFO] Quit: node-wikimon
2019-09-11 15:33:13.586 [main] KafkaSystemAdmin [INFO] Fetching SSP metadata for: [SystemStreamPartition [kafka, wikipedia-application-1-window-statsWindow, 0], SystemStreamPartition [kafka, wikipedia-stats-changelog, 0]]
2019-09-11 15:33:15.132 [Samza Container Shutdown Hook Thread] SamzaContainer [INFO] Shutting down, will wait up to 30000 ms.
2019-09-11 15:33:15.134 [main] SamzaContainer [INFO] Shutting down SamzaContainer.
2019-09-11 15:33:15.137 [main] SamzaContainer [INFO] Shutting down consumer multiplexer.
2019-09-11 15:33:15.183 [Thread-2] WikipediaFeed [INFO] #en.wikinews> samza-bot-404062277 parts
2019-09-11 15:33:15.198 [main] SamzaContainer [INFO] Shutting down task instance stream tasks.
2019-09-11 15:33:15.198 [main] SamzaContainer [INFO] Shutting down timer executor
2019-09-11 15:33:15.203 [main] SamzaContainer [INFO] Shutting down task instance table manager.
2019-09-11 15:33:15.204 [main] SamzaContainer [INFO] Shutting down container storage manager.
2019-09-11 15:33:15.207 [main] ContainerStorageManager [INFO] Shutdown complete
2019-09-11 15:33:15.207 [main] SamzaContainer [INFO] Shutting down host statistics monitor.
2019-09-11 15:33:15.208 [main] SamzaContainer [INFO] Shutting down producer multiplexer.
2019-09-11 15:33:15.209 [main] KafkaSystemProducer [INFO] Stopping producer for system: kafka
2019-09-11 15:33:15.209 [main] KafkaProducer [INFO] [Producer clientId=kafka_producer-wikipedia_application-1] Closing the Kafka producer with timeoutMillis = 9223372036854775807 ms.
2019-09-11 15:33:15.211 [main] SamzaContainer [INFO] Shutting down offset manager.
2019-09-11 15:33:15.212 [main] StartpointManager [WARN] already stopped
2019-09-11 15:33:15.213 [main] SamzaContainer [INFO] Shutting down metrics reporters.
2019-09-11 15:33:15.214 [main] MetricsSnapshotReporter [INFO] Stopping reporter timer.
2019-09-11 15:33:15.221 [main] MetricsSnapshotReporter [INFO] Stopping producer.
2019-09-11 15:33:15.221 [main] KafkaSystemProducer [INFO] Stopping producer for system: kafka
2019-09-11 15:33:15.222 [main] KafkaProducer [INFO] [Producer clientId=kafka_producer-wikipedia_application-1] Closing the Kafka producer with timeoutMillis = 9223372036854775807 ms.
2019-09-11 15:33:15.223 [main] SamzaContainer [INFO] Shutting down JVM metrics.
2019-09-11 15:33:15.223 [main] SamzaContainer [INFO] Shutting down admin multiplexer.
2019-09-11 15:33:15.227 [main] SamzaContainer [INFO] Shutdown complete.
2019-09-11 15:33:15.227 [main] ContainerLaunchUtil [INFO] Container Stopped
2019-09-11 15:33:15.227 [main] ContainerHeartbeatMonitor [INFO] Stopping ContainerHeartbeatMonitor
2019-09-11 15:33:15.227 [main] CoordinatorStreamStore [INFO] Stopping the coordinator stream system consumer.
2019-09-11 15:33:15.228 [main] KafkaSystemProducer [INFO] Stopping producer for system: kafka
2019-09-11 15:33:15.228 [main] KafkaProducer [INFO] [Producer clientId=kafka_producer-wikipedia_application-1] Closing the Kafka producer with timeoutMillis = 9223372036854775807 ms.
2019-09-11 15:33:15.229 [main] KafkaSystemConsumer [INFO] kafka:kafka_consumer-wikipedia_application-1: Stopping Samza kafkaConsumer
2019-09-11 15:33:15.229 [main] KafkaSystemConsumer [INFO] kafka:kafka_consumer-wikipedia_application-1: Stopping proxy consumerProxy-kafka-kafka_consumer-wikipedia_application-1
2019-09-11 15:33:15.229 [main] KafkaConsumerProxy [INFO] Shutting down KafkaConsumerProxy poll thread Samza KafkaConsumerProxy Poll Thread-1 - kafka for consumerProxy-kafka-kafka_consumer-wikipedia_application-1
2019-09-11 15:33:15.423 [Samza KafkaConsumerProxy Poll Thread-1 - kafka] KafkaConsumerProxy [INFO] KafkaConsumerProxy for system kafka has stopped.
2019-09-11 15:33:15.424 [main] KafkaSystemConsumer [INFO] kafka:kafka_consumer-wikipedia_application-1: Closing kafkaSystemConsumer org.apache.kafka.clients.consumer.KafkaConsumer@5717c37
2019-09-11 15:33:16.138 [Samza Container Shutdown Hook Thread] SamzaContainer [INFO] Shutdown complete
{noformat}
> Container process always takes task.shutdown.ms to shut down
> ------------------------------------------------------------
>
> Key: SAMZA-2198
> URL: https://issues.apache.org/jira/browse/SAMZA-2198
> Project: Samza
> Issue Type: Bug
> Affects Versions: 1.0, 1.1
> Reporter: Cameron Lee
> Priority: Major
> Time Spent: 10m
> Remaining Estimate: 0h
>
> https://issues.apache.org/jira/browse/SAMZA-1724 added a System.exit to LocalContainerRunner (now moved to ContainerLaunchUtil) in order to ensure the process exits. However, this seems to cause a partial deadlock when shutting down the container process. SamzaContainer adds a shutdown hook which joins on the run loop thread (which is also the main thread). During the shutdown process, when the main thread reaches the System.exit in ContainerLaunchUtil, it looks like it waits for the shutdown hook to complete. However, the shutdown hook is waiting for the main thread to join. Therefore, the shutdown hook will always wait task.shutdown.ms before giving up on joining the main thread, and then the process exits.
> This issue was not observed in a job on 0.14. The System.exit was only added in 1.0.
--
This message was sent by Atlassian Jira
(v8.3.2#803003)