Page MenuHomePhabricator
Files F41651407

Spark History Server can't parse large event log files
No One
Actions

Authored By
brouberol
Jan 5 2024, 9:21 AM
Size
29 KB
Referenced Files
None
Subscribers
None

Spark History Server can't parse large event log files
View Options

I've noticed that large enough (>40MB but it could start lower) spark event log files aren't being parsed successfully by the spark history server:
```
# ~40MB
24/01/05 08:18:00 INFO FsHistoryProvider: Parsing hdfs://analytics-hadoop/var/log/spark/application_1695896957545_622877 for listing data...
# ~40MB
24/01/05 08:18:00 INFO FsHistoryProvider: Parsing hdfs://analytics-hadoop/var/log/spark/application_1695896957545_622893.lz4 for listing data...
# ~40KB
24/01/05 08:18:01 INFO FsHistoryProvider: Parsing hdfs://analytics-hadoop/var/log/spark/application_1695896957545_622725 for listing data...
24/01/05 08:18:01 INFO FsHistoryProvider: Finished parsing hdfs://analytics-hadoop/var/log/spark/application_1695896957545_622893.lz4
# 40MB
24/01/05 08:18:01 INFO FsHistoryProvider: Parsing hdfs://analytics-hadoop/var/log/spark/application_1695896957545_622678.lz4 for listing data...
```
For the "large" files, we don't see the `Finished parsing` log, meaning that we're stuck somewhere in https://github.com/apache/spark/blob/fbbcf9434ac070dd4ced4fb9efe32899c6db12a9/core/src/main/scala/org/apache/spark/deploy/history/FsHistoryProvider.scala#L788-L835
We see the following HDFS audit logs on an-master1001.eqiad.wmnet:
```
2024-01-05 08:20:27,081 INFO FSNamesystem.audit: allowed=true ugi=spark/spark-history.svc.eqiad.wmnet@WIKIMEDIA (auth:KERBEROS) ip=/10.67.24.93 cmd=open src=/var/log/spark/application_1695896957545_622877 dst=null perm=null proto=rpc
2024-01-05 08:20:27,082 INFO FSNamesystem.audit: allowed=true ugi=spark/spark-history.svc.eqiad.wmnet@WIKIMEDIA (auth:KERBEROS) ip=/10.67.24.93 cmd=open src=/var/log/spark/application_1695896957545_622893.lz4dst=null perm=null proto=rpc
2024-01-05 08:20:27,550 INFO FSNamesystem.audit: allowed=true ugi=spark/spark-history.svc.eqiad.wmnet@WIKIMEDIA (auth:KERBEROS) ip=/10.67.24.93 cmd=open src=/var/log/spark/application_1695896957545_622725 dst=null perm=null proto=rpc
2024-01-05 08:20:27,555 INFO FSNamesystem.audit: allowed=true ugi=spark/spark-history.svc.eqiad.wmnet@WIKIMEDIA (auth:KERBEROS) ip=/10.67.24.93 cmd=open src=/var/log/spark/application_1695896957545_622893.lz4dst=null perm=null proto=rpc
2024-01-05 08:20:27,605 INFO FSNamesystem.audit: allowed=true ugi=spark/spark-history.svc.eqiad.wmnet@WIKIMEDIA (auth:KERBEROS) ip=/10.67.24.93 cmd=open src=/var/log/spark/application_1695896957545_622678.lz4dst=null perm=null proto=rpc
```
So this is not a permission issue. As we have a way to regenerate these "big" files by executing a Spark job from Jupyter, I decided to delete all these files from HDFS, to see what the system looks like when it has nothing to do. To do this, I ran `kill -3 <spark history server PID>` on the worker node the container was scheduled on.
```
24/01/05 08:27:53 INFO HistoryServer: Bound HistoryServer to 0.0.0.0, and started at http://spark-history-analytics-hadoop-57774468c-sn6vl:18080
2024-01-05 08:32:44
Full thread dump OpenJDK 64-Bit Server VM (11.0.21+9-post-Debian-1deb11u1 mixed mode, sharing):
Threads class SMR info:
_java_thread_list=0x00007f123c4f9650, length=23, elements={
0x00007f12f8019800, 0x00007f12f8b8e800, 0x00007f12f8b90800, 0x00007f12f8b97800,
0x00007f12f8b99800, 0x00007f12f8b9b800, 0x00007f12f8b9d800, 0x00007f12f8b9f800,
0x00007f12f8bef000, 0x00007f12faf2f800, 0x00007f12fb1c5000, 0x00007f12fb1c8000,
0x00007f12fb1ca000, 0x00007f12fb1cc000, 0x00007f12fb1cd800, 0x00007f12fb1d1000,
0x00007f12fb35f000, 0x00007f12fb368000, 0x00007f123005a800, 0x00007f1240005800,
0x00007f1248001800, 0x00007f1280268000, 0x00007f1248006000
}
"main" #1 prio=5 os_prio=0 cpu=2154.42ms elapsed=292.81s tid=0x00007f12f8019800 nid=0x1f waiting on condition [0x00007f12fdf44000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(java.base@11.0.21/Native Method)
at org.apache.spark.deploy.history.HistoryServer$.main(HistoryServer.scala:316)
at org.apache.spark.deploy.history.HistoryServer.main(HistoryServer.scala)
"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=1.31ms elapsed=292.78s tid=0x00007f12f8b8e800 nid=0x26 waiting on condition [0x00007f12c3379000]
java.lang.Thread.State: RUNNABLE
at java.lang.ref.Reference.waitForReferencePendingList(java.base@11.0.21/Native Method)
at java.lang.ref.Reference.processPendingReferences(java.base@11.0.21/Reference.java:241)
at java.lang.ref.Reference$ReferenceHandler.run(java.base@11.0.21/Reference.java:213)
"Finalizer" #3 daemon prio=8 os_prio=0 cpu=1.31ms elapsed=292.78s tid=0x00007f12f8b90800 nid=0x27 in Object.wait() [0x00007f12c3278000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(java.base@11.0.21/Native Method)
- waiting on <0x00000007fa8440d8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base@11.0.21/ReferenceQueue.java:155)
- waiting to re-lock in wait() <0x00000007fa8440d8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base@11.0.21/ReferenceQueue.java:176)
at java.lang.ref.Finalizer$FinalizerThread.run(java.base@11.0.21/Finalizer.java:170)
"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0.30ms elapsed=292.78s tid=0x00007f12f8b97800 nid=0x28 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Service Thread" #5 daemon prio=9 os_prio=0 cpu=0.17ms elapsed=292.78s tid=0x00007f12f8b99800 nid=0x29 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" #6 daemon prio=9 os_prio=0 cpu=2210.44ms elapsed=292.78s tid=0x00007f12f8b9b800 nid=0x2a waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
No compile task
"C1 CompilerThread0" #9 daemon prio=9 os_prio=0 cpu=1144.05ms elapsed=292.78s tid=0x00007f12f8b9d800 nid=0x2b waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
No compile task
"Sweeper thread" #10 daemon prio=9 os_prio=0 cpu=0.08ms elapsed=292.78s tid=0x00007f12f8b9f800 nid=0x2c runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Common-Cleaner" #11 daemon prio=8 os_prio=0 cpu=1.74ms elapsed=292.75s tid=0x00007f12f8bef000 nid=0x2e in Object.wait() [0x00007f12c29a9000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(java.base@11.0.21/Native Method)
- waiting on <0x00000007fa866368> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base@11.0.21/ReferenceQueue.java:155)
- waiting to re-lock in wait() <0x00000007fa866368> (a java.lang.ref.ReferenceQueue$Lock)
at jdk.internal.ref.CleanerImpl.run(java.base@11.0.21/CleanerImpl.java:148)
at java.lang.Thread.run(java.base@11.0.21/Thread.java:829)
at jdk.internal.misc.InnocuousThread.run(java.base@11.0.21/InnocuousThread.java:161)
"org.apache.hadoop.fs.FileSystem$Statistics$StatisticsDataReferenceCleaner" #15 daemon prio=5 os_prio=0 cpu=0.24ms elapsed=291.03s tid=0x00007f12faf2f800 nid=0x3c in Object.wait() [0x00007f12c0dd4000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(java.base@11.0.21/Native Method)
- waiting on <0x00000007fa888310> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base@11.0.21/ReferenceQueue.java:155)
- waiting to re-lock in wait() <0x00000007fa888310> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base@11.0.21/ReferenceQueue.java:176)
at org.apache.hadoop.fs.FileSystem$Statistics$StatisticsDataReferenceCleaner.run(FileSystem.java:3712)
at java.lang.Thread.run(java.base@11.0.21/Thread.java:829)
"HistoryServerUI-17" #17 daemon prio=5 os_prio=0 cpu=19.29ms elapsed=290.70s tid=0x00007f12fb1c5000 nid=0x3d runnable [0x00007f12c06d3000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPoll.wait(java.base@11.0.21/Native Method)
at sun.nio.ch.EPollSelectorImpl.doSelect(java.base@11.0.21/EPollSelectorImpl.java:120)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(java.base@11.0.21/SelectorImpl.java:124)
- locked <0x00000007fa866580> (a sun.nio.ch.Util$2)
- locked <0x00000007fa866528> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(java.base@11.0.21/SelectorImpl.java:141)
at org.sparkproject.jetty.io.ManagedSelector.nioSelect(ManagedSelector.java:183)
at org.sparkproject.jetty.io.ManagedSelector.select(ManagedSelector.java:190)
at org.sparkproject.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:606)
at org.sparkproject.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:543)
at org.sparkproject.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:362)
at org.sparkproject.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:186)
at org.sparkproject.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
at org.sparkproject.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
at org.sparkproject.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
at org.sparkproject.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
at org.sparkproject.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
at java.lang.Thread.run(java.base@11.0.21/Thread.java:829)
"HistoryServerUI-19-acceptor-0@4594c658-ServerConnector@4b53209a{HTTP/1.1, (http/1.1)}{0.0.0.0:18080}" #19 daemon prio=3 os_prio=0 cpu=17.86ms elapsed=290.69s tid=0x00007f12fb1c8000 nid=0x3f runnable [0x00007f12c04d1000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.ServerSocketChannelImpl.accept0(java.base@11.0.21/Native Method)
at sun.nio.ch.ServerSocketChannelImpl.accept(java.base@11.0.21/ServerSocketChannelImpl.java:533)
at sun.nio.ch.ServerSocketChannelImpl.accept(java.base@11.0.21/ServerSocketChannelImpl.java:285)
at org.sparkproject.jetty.server.ServerConnector.accept(ServerConnector.java:388)
at org.sparkproject.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:704)
at org.sparkproject.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
at org.sparkproject.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
at java.lang.Thread.run(java.base@11.0.21/Thread.java:829)
"HistoryServerUI-20" #20 daemon prio=5 os_prio=0 cpu=26.00ms elapsed=290.69s tid=0x00007f12fb1ca000 nid=0x40 runnable [0x00007f12c03d0000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPoll.wait(java.base@11.0.21/Native Method)
at sun.nio.ch.EPollSelectorImpl.doSelect(java.base@11.0.21/EPollSelectorImpl.java:120)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(java.base@11.0.21/SelectorImpl.java:124)
- locked <0x00000007fa8443f0> (a sun.nio.ch.Util$2)
- locked <0x00000007fa844398> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(java.base@11.0.21/SelectorImpl.java:141)
at org.sparkproject.jetty.io.ManagedSelector.nioSelect(ManagedSelector.java:183)
at org.sparkproject.jetty.io.ManagedSelector.select(ManagedSelector.java:190)
at org.sparkproject.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:606)
at org.sparkproject.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:543)
at org.sparkproject.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:362)
at org.sparkproject.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:186)
at org.sparkproject.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
at org.sparkproject.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
at org.sparkproject.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
at org.sparkproject.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
at org.sparkproject.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
at java.lang.Thread.run(java.base@11.0.21/Thread.java:829)
"HistoryServerUI-21" #21 daemon prio=5 os_prio=0 cpu=28.79ms elapsed=290.70s tid=0x00007f12fb1cc000 nid=0x41 waiting on condition [0x00007f12c02cf000]
java.lang.Thread.State: TIMED_WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@11.0.21/Native Method)
- parking to wait for <0x00000007fa888530> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.21/LockSupport.java:234)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@11.0.21/AbstractQueuedSynchronizer.java:2123)
at org.sparkproject.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:382)
at org.sparkproject.jetty.util.thread.QueuedThreadPool$Runner.idleJobPoll(QueuedThreadPool.java:974)
at org.sparkproject.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1018)
at java.lang.Thread.run(java.base@11.0.21/Thread.java:829)
"HistoryServerUI-22" #22 daemon prio=5 os_prio=0 cpu=52.92ms elapsed=290.69s tid=0x00007f12fb1cd800 nid=0x42 waiting on condition [0x00007f12c01ce000]
java.lang.Thread.State: TIMED_WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@11.0.21/Native Method)
- parking to wait for <0x00000007fa823470> (a java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.21/LockSupport.java:234)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@11.0.21/SynchronousQueue.java:462)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@11.0.21/SynchronousQueue.java:361)
at java.util.concurrent.SynchronousQueue.poll(java.base@11.0.21/SynchronousQueue.java:937)
at org.sparkproject.jetty.util.thread.ReservedThreadExecutor$ReservedThread.reservedWait(ReservedThreadExecutor.java:324)
at org.sparkproject.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:399)
at org.sparkproject.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
at org.sparkproject.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
at java.lang.Thread.run(java.base@11.0.21/Thread.java:829)
"HistoryServerUI-24" #24 daemon prio=5 os_prio=0 cpu=28.85ms elapsed=290.69s tid=0x00007f12fb1d1000 nid=0x44 waiting on condition [0x00007f1247efd000]
java.lang.Thread.State: TIMED_WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@11.0.21/Native Method)
- parking to wait for <0x00000007fa823470> (a java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.21/LockSupport.java:234)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@11.0.21/SynchronousQueue.java:462)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@11.0.21/SynchronousQueue.java:361)
at java.util.concurrent.SynchronousQueue.poll(java.base@11.0.21/SynchronousQueue.java:937)
at org.sparkproject.jetty.util.thread.ReservedThreadExecutor$ReservedThread.reservedWait(ReservedThreadExecutor.java:324)
at org.sparkproject.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:399)
at org.sparkproject.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
at org.sparkproject.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
at java.lang.Thread.run(java.base@11.0.21/Thread.java:829)
"IPC Parameter Sending Thread #0" #26 daemon prio=5 os_prio=0 cpu=60.27ms elapsed=290.51s tid=0x00007f12fb35f000 nid=0x46 waiting on condition [0x00007f12476d1000]
java.lang.Thread.State: TIMED_WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@11.0.21/Native Method)
- parking to wait for <0x00000007fa50d290> (a java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.21/LockSupport.java:234)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@11.0.21/SynchronousQueue.java:462)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@11.0.21/SynchronousQueue.java:361)
at java.util.concurrent.SynchronousQueue.poll(java.base@11.0.21/SynchronousQueue.java:937)
at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.21/ThreadPoolExecutor.java:1053)
at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.21/ThreadPoolExecutor.java:1114)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.21/ThreadPoolExecutor.java:628)
at java.lang.Thread.run(java.base@11.0.21/Thread.java:829)
"spark-history-task-0" #27 daemon prio=5 os_prio=0 cpu=71.26ms elapsed=290.49s tid=0x00007f12fb368000 nid=0x47 waiting on condition [0x00007f12473d0000]
java.lang.Thread.State: TIMED_WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@11.0.21/Native Method)
- parking to wait for <0x00000007fa6fc4a0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.21/LockSupport.java:234)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@11.0.21/AbstractQueuedSynchronizer.java:2123)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.21/ScheduledThreadPoolExecutor.java:1182)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.21/ScheduledThreadPoolExecutor.java:899)
at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.21/ThreadPoolExecutor.java:1054)
at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.21/ThreadPoolExecutor.java:1114)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.21/ThreadPoolExecutor.java:628)
at java.lang.Thread.run(java.base@11.0.21/Thread.java:829)
"IPC Client (137659163) connection to an-master1001.eqiad.wmnet/10.64.5.26:8020 from spark/spark-history.svc.eqiad.wmnet@WIKIMEDIA" #28 daemon prio=5 os_prio=0 cpu=71.32ms elapsed=280.46s tid=0x00007f123005a800 nid=0x48 in Object.wait() [0x00007f12477d2000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(java.base@11.0.21/Native Method)
- waiting on <0x00000007ff36e8f0> (a org.apache.hadoop.ipc.Client$Connection)
at org.apache.hadoop.ipc.Client$Connection.waitForWork(Client.java:1053)
- waiting to re-lock in wait() <0x00000007ff36e8f0> (a org.apache.hadoop.ipc.Client$Connection)
at org.apache.hadoop.ipc.Client$Connection.run(Client.java:1097)
"HistoryServerUI-JettyScheduler-1" #29 daemon prio=5 os_prio=0 cpu=6.12ms elapsed=273.97s tid=0x00007f1240005800 nid=0x49 waiting on condition [0x00007f12c284c000]
java.lang.Thread.State: TIMED_WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@11.0.21/Native Method)
- parking to wait for <0x00000007fa823180> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.21/LockSupport.java:234)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@11.0.21/AbstractQueuedSynchronizer.java:2123)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.21/ScheduledThreadPoolExecutor.java:1182)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.21/ScheduledThreadPoolExecutor.java:899)
at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.21/ThreadPoolExecutor.java:1054)
at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.21/ThreadPoolExecutor.java:1114)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.21/ThreadPoolExecutor.java:628)
at java.lang.Thread.run(java.base@11.0.21/Thread.java:829)
"HistoryServerUI-30" #30 daemon prio=5 os_prio=0 cpu=39.29ms elapsed=273.93s tid=0x00007f1248001800 nid=0x4a waiting on condition [0x00007f12c274b000]
java.lang.Thread.State: TIMED_WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@11.0.21/Native Method)
- parking to wait for <0x00000007fa823470> (a java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.21/LockSupport.java:234)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@11.0.21/SynchronousQueue.java:462)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@11.0.21/SynchronousQueue.java:361)
at java.util.concurrent.SynchronousQueue.poll(java.base@11.0.21/SynchronousQueue.java:937)
at org.sparkproject.jetty.util.thread.ReservedThreadExecutor$ReservedThread.reservedWait(ReservedThreadExecutor.java:324)
at org.sparkproject.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:399)
at org.sparkproject.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
at org.sparkproject.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
at java.lang.Thread.run(java.base@11.0.21/Thread.java:829)
"HistoryServerUI-31" #31 daemon prio=5 os_prio=0 cpu=38.29ms elapsed=273.93s tid=0x00007f1280268000 nid=0x4b runnable [0x00007f1247bfc000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPoll.wait(java.base@11.0.21/Native Method)
at sun.nio.ch.EPollSelectorImpl.doSelect(java.base@11.0.21/EPollSelectorImpl.java:120)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(java.base@11.0.21/SelectorImpl.java:124)
- locked <0x00000007fa8229b0> (a sun.nio.ch.Util$2)
- locked <0x00000007fa822958> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(java.base@11.0.21/SelectorImpl.java:141)
at org.sparkproject.jetty.io.ManagedSelector.nioSelect(ManagedSelector.java:183)
at org.sparkproject.jetty.io.ManagedSelector.select(ManagedSelector.java:190)
at org.sparkproject.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:606)
at org.sparkproject.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:543)
at org.sparkproject.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:362)
at org.sparkproject.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:186)
at org.sparkproject.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
at org.sparkproject.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
at org.sparkproject.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
at org.sparkproject.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
at org.sparkproject.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
at java.lang.Thread.run(java.base@11.0.21/Thread.java:829)
"HistoryServerUI-34" #34 daemon prio=5 os_prio=0 cpu=7.23ms elapsed=63.98s tid=0x00007f1248006000 nid=0x51 runnable [0x00007f12c05d2000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPoll.wait(java.base@11.0.21/Native Method)
at sun.nio.ch.EPollSelectorImpl.doSelect(java.base@11.0.21/EPollSelectorImpl.java:120)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(java.base@11.0.21/SelectorImpl.java:124)
- locked <0x00000007fa8cc488> (a sun.nio.ch.Util$2)
- locked <0x00000007fa8cc430> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(java.base@11.0.21/SelectorImpl.java:141)
at org.sparkproject.jetty.io.ManagedSelector.nioSelect(ManagedSelector.java:183)
at org.sparkproject.jetty.io.ManagedSelector.select(ManagedSelector.java:190)
at org.sparkproject.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:606)
at org.sparkproject.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:543)
at org.sparkproject.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:362)
at org.sparkproject.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:186)
at org.sparkproject.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
at org.sparkproject.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
at org.sparkproject.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
at org.sparkproject.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
at org.sparkproject.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
at java.lang.Thread.run(java.base@11.0.21/Thread.java:829)
"VM Thread" os_prio=0 cpu=93.44ms elapsed=292.79s tid=0x00007f12f8b8b800 nid=0x25 runnable
"GC Thread#0" os_prio=0 cpu=55.00ms elapsed=292.81s tid=0x00007f12f8031000 nid=0x20 runnable
"GC Thread#1" os_prio=0 cpu=55.63ms elapsed=291.32s tid=0x00007f12b4001000 nid=0x34 runnable
"GC Thread#2" os_prio=0 cpu=46.13ms elapsed=291.32s tid=0x00007f12b4002000 nid=0x35 runnable
"GC Thread#3" os_prio=0 cpu=59.08ms elapsed=291.32s tid=0x00007f12b4003800 nid=0x36 runnable
"GC Thread#4" os_prio=0 cpu=58.77ms elapsed=291.32s tid=0x00007f12b4005800 nid=0x37 runnable
"GC Thread#5" os_prio=0 cpu=55.57ms elapsed=291.32s tid=0x00007f12b4007000 nid=0x38 runnable
"GC Thread#6" os_prio=0 cpu=55.33ms elapsed=291.32s tid=0x00007f12b4009000 nid=0x39 runnable
"GC Thread#7" os_prio=0 cpu=54.61ms elapsed=291.32s tid=0x00007f12b400a800 nid=0x3a runnable
"G1 Main Marker" os_prio=0 cpu=1.38ms elapsed=292.81s tid=0x00007f12f8053000 nid=0x21 runnable
"G1 Conc#0" os_prio=0 cpu=51.00ms elapsed=292.81s tid=0x00007f12f8055000 nid=0x22 runnable
"G1 Conc#1" os_prio=0 cpu=45.61ms elapsed=291.31s tid=0x00007f12c4001000 nid=0x3b runnable
"G1 Refine#0" os_prio=0 cpu=0.16ms elapsed=292.80s tid=0x00007f12f8b58000 nid=0x23 runnable
"G1 Young RemSet Sampling" os_prio=0 cpu=45.92ms elapsed=292.80s tid=0x00007f12f8b5a000 nid=0x24 runnable
"VM Periodic Task Thread" os_prio=0 cpu=199.62ms elapsed=292.76s tid=0x00007f12f8be8800 nid=0x2d waiting on condition
JNI global refs: 20, weak refs: 0
Heap
garbage-first heap total 8388608K, used 75734K [0x0000000600000000, 0x0000000800000000)
region size 4096K, 19 young (77824K), 6 survivors (24576K)
Metaspace used 39853K, capacity 40854K, committed 41216K, reserved 1085440K
class space used 5315K, capacity 5794K, committed 5888K, reserved 1048576K
```
We see the following thread:
```
"IPC Client (137659163) connection to an-master1001.eqiad.wmnet/10.64.5.26:8020 from spark/spark-history.svc.eqiad.wmnet@WIKIMEDIA" #28 daemon prio=5 os_prio=0 cpu=71.32ms elapsed=280.46s tid=0x00007f123005a800 nid=0x48 in Object.wait() [0x00007f12477d2000]
```
I initially thought that thread was blocking in the case of the "large" files, but it seems that it's a long running connection, not a data transfer thread.
I had already taken another thread dump of the spark history server (at a time where 2 large files were in HDFS), and wrote a small python script that nicely formats the thread names and their associate state:
```python
import sys
logfile = sys.argv[1]
thread_states = {}
for line in open(logfile):
if line.startswith('"'):
thread_name = line.split('"')[1]
thread_states[thread_name] = None
elif line.strip().startswith('java.lang.Thread.State: '):
thread_states[thread_name] = line.split(": ")[1].strip()
thread_states = {k: v for k, v in thread_states.items() if v is not None}
for thread, state in sorted(thread_states.items()):
print(thread, state)
```
This allowed me to print a diff of both JVM states:
```diff
--- thread-state-empty-hdfs.txt 2024-01-05 10:08:18
+++ thread-state-shs.txt 2024-01-05 10:08:27
@@ -2,22 +2,25 @@
C2 CompilerThread0 RUNNABLE
Common-Cleaner TIMED_WAITING (on object monitor)
Finalizer WAITING (on object monitor)
-HistoryServerUI-17 RUNNABLE
-HistoryServerUI-19-acceptor-0@4594c658-ServerConnector@4b53209a{HTTP/1.1, (http/1.1)}{0.0.0.0:18080} RUNNABLE
-HistoryServerUI-20 RUNNABLE
-HistoryServerUI-21 TIMED_WAITING (parking)
-HistoryServerUI-22 TIMED_WAITING (parking)
-HistoryServerUI-24 TIMED_WAITING (parking)
-HistoryServerUI-30 TIMED_WAITING (parking)
-HistoryServerUI-31 RUNNABLE
-HistoryServerUI-34 RUNNABLE
+HistoryServerUI-24-acceptor-0@49f6bda8-ServerConnector@47315ae6{HTTP/1.1, (http/1.1)}{0.0.0.0:18080} RUNNABLE
+HistoryServerUI-44 RUNNABLE
+HistoryServerUI-46 TIMED_WAITING (parking)
+HistoryServerUI-49 RUNNABLE
+HistoryServerUI-51 TIMED_WAITING (parking)
+HistoryServerUI-52 TIMED_WAITING (parking)
+HistoryServerUI-53 TIMED_WAITING (parking)
+HistoryServerUI-54 RUNNABLE
+HistoryServerUI-55 RUNNABLE
HistoryServerUI-JettyScheduler-1 TIMED_WAITING (parking)
-IPC Client (137659163) connection to an-master1001.eqiad.wmnet/10.64.5.26:8020 from spark/spark-history.svc.eqiad.wmnet@WIKIMEDIA TIMED_WAITING (on object monitor)
+IPC Client (1196716338) connection to an-master1001.eqiad.wmnet/10.64.5.26:8020 from spark/spark-history.svc.eqiad.wmnet@WIKIMEDIA TIMED_WAITING (on object monitor)
IPC Parameter Sending Thread #0 TIMED_WAITING (parking)
Reference Handler RUNNABLE
Service Thread RUNNABLE
Signal Dispatcher RUNNABLE
Sweeper thread RUNNABLE
+log-replay-executor-0 WAITING (parking)
+log-replay-executor-1 WAITING (parking)
main TIMED_WAITING (sleeping)
org.apache.hadoop.fs.FileSystem$Statistics$StatisticsDataReferenceCleaner WAITING (on object monitor)
+org.apache.hadoop.hdfs.PeerCache@62a7c7ba TIMED_WAITING (sleeping)
spark-history-task-0 TIMED_WAITING (parking)
```
We see that 2 `log-replay-executor` threads are in WAITING state:
```diff
+log-replay-executor-0 WAITING (parking)
+log-replay-executor-1 WAITING (parking)
```
I'm not sure whether they are blocked on receiving the file, or if the receiving of the file failed, and the threads are waiting for something else to do.

File Metadata

Mime Type
text/plain; charset=utf-8
Storage Engine
blob
Storage Format
Raw Data
Storage Handle
14451736
Default Alt Text
Spark History Server can't parse large event log files (29 KB)

Event Timeline

Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL · Credits