holdenk commented on pull request #28370:
URL: https://github.com/apache/spark/pull/28370#issuecomment-622194444
Looks like the tests are passing but were still seeing the executor hang, I
did a jstack dump on a local run and I got:
> 2020-04-30 17:44:40
> Full thread dump OpenJDK 64-Bit Server VM
(11.0.7+10-post-Ubuntu-2ubuntu218.04 mixed mode, sharing):
>
> Threads class SMR info:
> _java_thread_list=0x00007f06dc00c9d0, length=21, elements={
> 0x00007f0720021000, 0x00007f072030a000, 0x00007f072030c000,
0x00007f0720311800,
> 0x00007f0720313800, 0x00007f0720316000, 0x00007f0720318000,
0x00007f072035b800,
> 0x00007f0720325800, 0x00007f068c03e000, 0x00007f0723545800,
0x00007f06dc001000,
> 0x00007f0648005800, 0x00007f06dc003000, 0x00007f06dc004000,
0x00007f06dc005000,
> 0x00007f06dc006800, 0x00007f06dc007800, 0x00007f06dc008800,
0x00007f06dc00a000,
> 0x00007f06dc00b800
> }
>
> "main" #1 prio=5 os_prio=0 cpu=1980.18ms elapsed=30291.61s
tid=0x00007f0720021000 nid=0x64be waiting on condition [0x00007f072a3f6000]
> java.lang.Thread.State: WAITING (parking)
> at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
> - parking to wait for <0x00000000eab00038> (a
java.util.concurrent.CountDownLatch$Sync)
> at
java.util.concurrent.locks.LockSupport.park([email protected]/LockSupport.java:194)
> at
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt([email protected]/AbstractQueuedSynchronizer.java:885)
> at
java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly([email protected]/AbstractQueuedSynchronizer.java:1039)
> at
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly([email protected]/AbstractQueuedSynchronizer.java:1345)
> at
java.util.concurrent.CountDownLatch.await([email protected]/CountDownLatch.java:232)
> at
org.apache.spark.rpc.netty.Dispatcher.awaitTermination(Dispatcher.scala:202)
> at
org.apache.spark.rpc.netty.NettyRpcEnv.awaitTermination(NettyRpcEnv.scala:313)
> at
org.apache.spark.executor.CoarseGrainedExecutorBackend$.$anonfun$run$1(CoarseGrainedExecutorBackend.scala:377)
> at
org.apache.spark.executor.CoarseGrainedExecutorBackend$$$Lambda$184/0x000000084024f840.apply$mcV$sp(Unknown
Source)
> at
org.apache.spark.deploy.SparkHadoopUtil$$anon$1.run(SparkHadoopUtil.scala:62)
> at
org.apache.spark.deploy.SparkHadoopUtil$$anon$1.run(SparkHadoopUtil.scala:61)
> at java.security.AccessController.doPrivileged([email protected]/Native
Method)
> at javax.security.auth.Subject.doAs([email protected]/Subject.java:423)
> at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1746)
> at
org.apache.spark.deploy.SparkHadoopUtil.runAsSparkUser(SparkHadoopUtil.scala:61)
> at
org.apache.spark.executor.CoarseGrainedExecutorBackend$.run(CoarseGrainedExecutorBackend.scala:321)
> at
org.apache.spark.executor.CoarseGrainedExecutorBackend$.main(CoarseGrainedExecutorBackend.scala:310)
> at
org.apache.spark.executor.CoarseGrainedExecutorBackend.main(CoarseGrainedExecutorBackend.scala)
>
> "Reference Handler" #2 daemon prio=10 os_prio=0 cpu=1.17ms
elapsed=30291.59s tid=0x00007f072030a000 nid=0x64c5 waiting on condition
[0x00007f07003f7000]
> java.lang.Thread.State: RUNNABLE
> at
java.lang.ref.Reference.waitForReferencePendingList([email protected]/Native
Method)
> at
java.lang.ref.Reference.processPendingReferences([email protected]/Reference.java:241)
> at
java.lang.ref.Reference$ReferenceHandler.run([email protected]/Reference.java:213)
>
> "Finalizer" #3 daemon prio=8 os_prio=0 cpu=0.54ms elapsed=30291.59s
tid=0x00007f072030c000 nid=0x64c6 in Object.wait() [0x00007f07002f6000]
> java.lang.Thread.State: WAITING (on object monitor)
> at java.lang.Object.wait([email protected]/Native Method)
> - waiting on <0x00000000c0b7af38> (a java.lang.ref.ReferenceQueue$Lock)
> at
java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:155)
> - waiting to re-lock in wait() <0x00000000c0b7af38> (a
java.lang.ref.ReferenceQueue$Lock)
> at
java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:176)
> at
java.lang.ref.Finalizer$FinalizerThread.run([email protected]/Finalizer.java:170)
>
> "Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=2.29ms
elapsed=30291.59s tid=0x00007f0720311800 nid=0x64c7 runnable
[0x0000000000000000]
> java.lang.Thread.State: RUNNABLE
>
> "C2 CompilerThread0" #5 daemon prio=9 os_prio=0 cpu=2311.78ms
elapsed=30291.59s tid=0x00007f0720313800 nid=0x64c8 waiting on condition
[0x0000000000000000]
> java.lang.Thread.State: RUNNABLE
> No compile task
>
> "C1 CompilerThread0" #8 daemon prio=9 os_prio=0 cpu=1164.60ms
elapsed=30291.59s tid=0x00007f0720316000 nid=0x64c9 waiting on condition
[0x0000000000000000]
> java.lang.Thread.State: RUNNABLE
> No compile task
>
> "Sweeper thread" #9 daemon prio=9 os_prio=0 cpu=26.03ms elapsed=30291.59s
tid=0x00007f0720318000 nid=0x64ca runnable [0x0000000000000000]
> java.lang.Thread.State: RUNNABLE
>
> "Service Thread" #10 daemon prio=9 os_prio=0 cpu=0.07ms elapsed=30291.55s
tid=0x00007f072035b800 nid=0x64cb runnable [0x0000000000000000]
> java.lang.Thread.State: RUNNABLE
>
> "Common-Cleaner" #11 daemon prio=8 os_prio=0 cpu=31.46ms elapsed=30291.54s
tid=0x00007f0720325800 nid=0x64cd in Object.wait() [0x00007f06e3129000]
> java.lang.Thread.State: TIMED_WAITING (on object monitor)
> at java.lang.Object.wait([email protected]/Native Method)
> - waiting on <no object reference available>
> at
java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:155)
> - waiting to re-lock in wait() <0x00000000c0b7b8e0> (a
java.lang.ref.ReferenceQueue$Lock)
> at
jdk.internal.ref.CleanerImpl.run([email protected]/CleanerImpl.java:148)
> at java.lang.Thread.run([email protected]/Thread.java:834)
> at
jdk.internal.misc.InnocuousThread.run([email protected]/InnocuousThread.java:134)
>
> "rpc-client-3-1" #27 daemon prio=5 os_prio=0 cpu=39.52ms elapsed=30289.23s
tid=0x00007f068c03e000 nid=0x6644 runnable [0x00007f068aaf8000]
> java.lang.Thread.State: RUNNABLE
> at sun.nio.ch.EPoll.wait([email protected]/Native Method)
> at
sun.nio.ch.EPollSelectorImpl.doSelect([email protected]/EPollSelectorImpl.java:120)
> at
sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:124)
> - locked <0x00000000eab87020> (a
io.netty.channel.nio.SelectedSelectionKeySet)
> - locked <0x00000000eab7ba68> (a sun.nio.ch.EPollSelectorImpl)
> at
sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:141)
> at
io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:68)
> at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:803)
> at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:457)
> at
io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
> at
io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
> at
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
> at java.lang.Thread.run([email protected]/Thread.java:834)
>
> "dispatcher-event-loop-0" #33 daemon prio=5 os_prio=0 cpu=1.70ms
elapsed=30288.82s tid=0x00007f0723545800 nid=0x6695 in Object.wait()
[0x00007f06891f1000]
> java.lang.Thread.State: WAITING (on object monitor)
> at java.lang.Object.wait([email protected]/Native Method)
> - waiting on <0x00000000ea79ff18> (a
org.apache.hadoop.util.ShutdownHookManager$1)
> at java.lang.Thread.join([email protected]/Thread.java:1305)
> - waiting to re-lock in wait() <0x00000000ea79ff18> (a
org.apache.hadoop.util.ShutdownHookManager$1)
> at java.lang.Thread.join([email protected]/Thread.java:1379)
> at
java.lang.ApplicationShutdownHooks.runHooks([email protected]/ApplicationShutdownHooks.java:107)
> at
java.lang.ApplicationShutdownHooks$1.run([email protected]/ApplicationShutdownHooks.java:46)
> at java.lang.Shutdown.runHooks([email protected]/Shutdown.java:130)
> at java.lang.Shutdown.exit([email protected]/Shutdown.java:174)
> - locked <0x00000000ffc180f8> (a java.lang.Class for java.lang.Shutdown)
> at java.lang.Runtime.exit([email protected]/Runtime.java:116)
> at java.lang.System.exit([email protected]/System.java:1749)
> at
org.apache.spark.deploy.worker.WorkerWatcher.exitNonZero(WorkerWatcher.scala:48)
> at
org.apache.spark.deploy.worker.WorkerWatcher.onDisconnected(WorkerWatcher.scala:64)
> at org.apache.spark.rpc.netty.Inbox.$anonfun$process$1(Inbox.scala:141)
> at
org.apache.spark.rpc.netty.Inbox$$Lambda$346/0x00000008403c6040.apply$mcV$sp(Unknown
Source)
> at org.apache.spark.rpc.netty.Inbox.safelyCall(Inbox.scala:203)
> at org.apache.spark.rpc.netty.Inbox.process(Inbox.scala:100)
> at
org.apache.spark.rpc.netty.MessageLoop.org$apache$spark$rpc$netty$MessageLoop$$receiveLoop(MessageLoop.scala:75)
> at
org.apache.spark.rpc.netty.MessageLoop$$anon$1.run(MessageLoop.scala:41)
> at
java.util.concurrent.ThreadPoolExecutor.runWorker([email protected]/ThreadPoolExecutor.java:1128)
> at
java.util.concurrent.ThreadPoolExecutor$Worker.run([email protected]/ThreadPoolExecutor.java:628)
> at java.lang.Thread.run([email protected]/Thread.java:834)
>
> "SIGTERM handler" #39 daemon prio=9 os_prio=0 cpu=940.87ms
elapsed=30287.87s tid=0x00007f06dc001000 nid=0x66ff waiting for monitor entry
[0x00007f0636dfd000]
> java.lang.Thread.State: BLOCKED (on object monitor)
> at java.lang.Shutdown.exit([email protected]/Shutdown.java:173)
> - waiting to lock <0x00000000ffc180f8> (a java.lang.Class for
java.lang.Shutdown)
> at java.lang.Terminator$1.handle([email protected]/Terminator.java:51)
> at
sun.misc.Signal$SunMiscHandler.handle([email protected]/Signal.java:228)
> at
org.apache.spark.util.SignalUtils$ActionHandler.handle(SignalUtils.scala:124)
> at
sun.misc.Signal$InternalMiscHandler.handle([email protected]/Signal.java:198)
> at jdk.internal.misc.Signal$1.run([email protected]/Signal.java:220)
> at java.lang.Thread.run([email protected]/Thread.java:834)
>
> "Thread-1" #28 prio=5 os_prio=0 cpu=9.74ms elapsed=30287.86s
tid=0x00007f0648005800 nid=0x6701 waiting on condition [0x00007f0636cfb000]
> java.lang.Thread.State: TIMED_WAITING (parking)
> at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
> - parking to wait for <0x00000000eaa079d8> (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> at
java.util.concurrent.locks.LockSupport.parkNanos([email protected]/LockSupport.java:234)
> at
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos([email protected]/AbstractQueuedSynchronizer.java:2123)
> at
java.util.concurrent.ThreadPoolExecutor.awaitTermination([email protected]/ThreadPoolExecutor.java:1454)
> at org.apache.spark.rpc.netty.MessageLoop.stop(MessageLoop.scala:60)
> at org.apache.spark.rpc.netty.Dispatcher.stop(Dispatcher.scala:196)
> at org.apache.spark.rpc.netty.NettyRpcEnv.cleanup(NettyRpcEnv.scala:331)
> at
org.apache.spark.rpc.netty.NettyRpcEnv.shutdown(NettyRpcEnv.scala:309)
> at org.apache.spark.SparkEnv.stop(SparkEnv.scala:96)
> at org.apache.spark.executor.Executor.stop(Executor.scala:306)
> at org.apache.spark.executor.Executor.$anonfun$new$2(Executor.scala:74)
> at
org.apache.spark.executor.Executor$$Lambda$408/0x0000000840449c40.apply$mcV$sp(Unknown
Source)
> at
org.apache.spark.util.SparkShutdownHook.run(ShutdownHookManager.scala:216)
> at
org.apache.spark.util.SparkShutdownHookManager.$anonfun$runAll$2(ShutdownHookManager.scala:188)
> at
org.apache.spark.util.SparkShutdownHookManager$$Lambda$629/0x00000008405d2040.apply$mcV$sp(Unknown
Source)
> at
scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
> at org.apache.spark.util.Utils$.logUncaughtExceptions(Utils.scala:1932)
> at
org.apache.spark.util.SparkShutdownHookManager.$anonfun$runAll$1(ShutdownHookManager.scala:188)
> at
org.apache.spark.util.SparkShutdownHookManager$$Lambda$628/0x00000008405d1440.apply$mcV$sp(Unknown
Source)
> at
scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
> at scala.util.Try$.apply(Try.scala:213)
> at
org.apache.spark.util.SparkShutdownHookManager.runAll(ShutdownHookManager.scala:188)
> at
org.apache.spark.util.SparkShutdownHookManager$$anon$2.run(ShutdownHookManager.scala:178)
> at
org.apache.hadoop.util.ShutdownHookManager$1.run(ShutdownHookManager.java:54)
>
> "SIGINT handler" #45 daemon prio=9 os_prio=0 cpu=0.95ms elapsed=24379.32s
tid=0x00007f06dc003000 nid=0x1197 waiting for monitor entry
[0x00007f06892f3000]
> java.lang.Thread.State: BLOCKED (on object monitor)
> at java.lang.Shutdown.exit([email protected]/Shutdown.java:173)
> - waiting to lock <0x00000000ffc180f8> (a java.lang.Class for
java.lang.Shutdown)
> at java.lang.Terminator$1.handle([email protected]/Terminator.java:51)
> at
sun.misc.Signal$SunMiscHandler.handle([email protected]/Signal.java:228)
> at
org.apache.spark.util.SignalUtils$ActionHandler.handle(SignalUtils.scala:124)
> at
sun.misc.Signal$InternalMiscHandler.handle([email protected]/Signal.java:198)
> at jdk.internal.misc.Signal$1.run([email protected]/Signal.java:220)
> at java.lang.Thread.run([email protected]/Thread.java:834)
>
> "SIGINT handler" #46 daemon prio=9 os_prio=0 cpu=0.10ms elapsed=24378.94s
tid=0x00007f06dc004000 nid=0x11b2 waiting for monitor entry
[0x00007f06e10bc000]
> java.lang.Thread.State: BLOCKED (on object monitor)
> at java.lang.Shutdown.exit([email protected]/Shutdown.java:173)
> - waiting to lock <0x00000000ffc180f8> (a java.lang.Class for
java.lang.Shutdown)
> at java.lang.Terminator$1.handle([email protected]/Terminator.java:51)
> at jdk.internal.misc.Signal$1.run([email protected]/Signal.java:220)
> at java.lang.Thread.run([email protected]/Thread.java:834)
>
> "SIGTERM handler" #47 daemon prio=9 os_prio=0 cpu=0.11ms elapsed=238.61s
tid=0x00007f06dc005000 nid=0x76ac waiting for monitor entry
[0x00007f06e1fed000]
> java.lang.Thread.State: BLOCKED (on object monitor)
> at java.lang.Shutdown.exit([email protected]/Shutdown.java:173)
> - waiting to lock <0x00000000ffc180f8> (a java.lang.Class for
java.lang.Shutdown)
> at java.lang.Terminator$1.handle([email protected]/Terminator.java:51)
> at jdk.internal.misc.Signal$1.run([email protected]/Signal.java:220)
> at java.lang.Thread.run([email protected]/Thread.java:834)
>
> "SIGTERM handler" #48 daemon prio=9 os_prio=0 cpu=0.32ms elapsed=237.96s
tid=0x00007f06dc006800 nid=0x76ad waiting for monitor entry
[0x00007f06887ec000]
> java.lang.Thread.State: BLOCKED (on object monitor)
> at java.lang.Shutdown.exit([email protected]/Shutdown.java:173)
> - waiting to lock <0x00000000ffc180f8> (a java.lang.Class for
java.lang.Shutdown)
> at java.lang.Terminator$1.handle([email protected]/Terminator.java:51)
> at jdk.internal.misc.Signal$1.run([email protected]/Signal.java:220)
> at java.lang.Thread.run([email protected]/Thread.java:834)
>
> "SIGTERM handler" #49 daemon prio=9 os_prio=0 cpu=0.39ms elapsed=237.36s
tid=0x00007f06dc007800 nid=0x76c0 waiting for monitor entry
[0x00007f06888ed000]
> java.lang.Thread.State: BLOCKED (on object monitor)
> at java.lang.Shutdown.exit([email protected]/Shutdown.java:173)
> - waiting to lock <0x00000000ffc180f8> (a java.lang.Class for
java.lang.Shutdown)
> at java.lang.Terminator$1.handle([email protected]/Terminator.java:51)
> at jdk.internal.misc.Signal$1.run([email protected]/Signal.java:220)
> at java.lang.Thread.run([email protected]/Thread.java:834)
>
> "SIGTERM handler" #50 daemon prio=9 os_prio=0 cpu=0.44ms elapsed=236.78s
tid=0x00007f06dc008800 nid=0x76d4 waiting for monitor entry
[0x00007f0688cef000]
> java.lang.Thread.State: BLOCKED (on object monitor)
> at java.lang.Shutdown.exit([email protected]/Shutdown.java:173)
> - waiting to lock <0x00000000ffc180f8> (a java.lang.Class for
java.lang.Shutdown)
> at java.lang.Terminator$1.handle([email protected]/Terminator.java:51)
> at jdk.internal.misc.Signal$1.run([email protected]/Signal.java:220)
> at java.lang.Thread.run([email protected]/Thread.java:834)
>
> "SIGTERM handler" #51 daemon prio=9 os_prio=0 cpu=0.12ms elapsed=235.91s
tid=0x00007f06dc00a000 nid=0x770d waiting for monitor entry
[0x00007f068aefc000]
> java.lang.Thread.State: BLOCKED (on object monitor)
> at java.lang.Shutdown.exit([email protected]/Shutdown.java:173)
> - waiting to lock <0x00000000ffc180f8> (a java.lang.Class for
java.lang.Shutdown)
> at java.lang.Terminator$1.handle([email protected]/Terminator.java:51)
> at jdk.internal.misc.Signal$1.run([email protected]/Signal.java:220)
> at java.lang.Thread.run([email protected]/Thread.java:834)
>
> "Attach Listener" #52 daemon prio=9 os_prio=0 cpu=0.43ms elapsed=0.10s
tid=0x00007f06dc00b800 nid=0xc4b waiting on condition [0x0000000000000000]
> java.lang.Thread.State: RUNNABLE
>
> "VM Thread" os_prio=0 cpu=1040.62ms elapsed=30291.60s
tid=0x00007f0720307000 nid=0x64c4 runnable
>
> "GC Thread#0" os_prio=0 cpu=34.03ms elapsed=30291.61s
tid=0x00007f072003a800 nid=0x64bf runnable
>
> "GC Thread#1" os_prio=0 cpu=40.77ms elapsed=30290.94s
tid=0x00007f06f0001000 nid=0x6577 runnable
>
> "GC Thread#2" os_prio=0 cpu=32.22ms elapsed=30290.94s
tid=0x00007f06f0002800 nid=0x6578 runnable
>
> "GC Thread#3" os_prio=0 cpu=24.04ms elapsed=30290.94s
tid=0x00007f06f0004000 nid=0x657a runnable
>
> "GC Thread#4" os_prio=0 cpu=46.37ms elapsed=30290.94s
tid=0x00007f06f0005800 nid=0x657b runnable
>
> "GC Thread#5" os_prio=0 cpu=30.93ms elapsed=30290.94s
tid=0x00007f06f0007000 nid=0x657c runnable
>
> "GC Thread#6" os_prio=0 cpu=33.78ms elapsed=30290.94s
tid=0x00007f06f0008800 nid=0x657e runnable
>
> "GC Thread#7" os_prio=0 cpu=38.40ms elapsed=30290.94s
tid=0x00007f06f000a000 nid=0x6580 runnable
>
> "GC Thread#8" os_prio=0 cpu=33.33ms elapsed=30290.94s
tid=0x00007f06f000c000 nid=0x6582 runnable
>
> "GC Thread#9" os_prio=0 cpu=29.62ms elapsed=30290.94s
tid=0x00007f06f000d800 nid=0x6584 runnable
>
> "G1 Main Marker" os_prio=0 cpu=1.26ms elapsed=30291.61s
tid=0x00007f0720056800 nid=0x64c0 runnable
>
> "G1 Conc#0" os_prio=0 cpu=26.48ms elapsed=30291.61s tid=0x00007f0720058000
nid=0x64c1 runnable
>
> "G1 Conc#1" os_prio=0 cpu=19.97ms elapsed=30289.71s tid=0x00007f06fc001000
nid=0x6624 runnable
>
> "G1 Conc#2" os_prio=0 cpu=10.23ms elapsed=30289.69s tid=0x00007f06fc002000
nid=0x6626 runnable
>
> "G1 Refine#0" os_prio=0 cpu=2.22ms elapsed=30291.60s
tid=0x00007f07202d7800 nid=0x64c2 runnable
>
> "G1 Young RemSet Sampling" os_prio=0 cpu=7065.00ms elapsed=30291.60s
tid=0x00007f07202d9800 nid=0x64c3 runnable
> "VM Periodic Task Thread" os_prio=0 cpu=21618.50ms elapsed=30291.55s
tid=0x00007f072035d800 nid=0x64cc waiting on condition
>
> JNI global refs: 27, weak refs: 0
>
I'm going to try and figure out why the shutdown threads are blocking but
just figured I'd share the context incase you've got the time to get to it
before I do :)
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
[email protected]
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
