My question is how to debug/investigate a following scenario. It occurs quite often in my case, every time it looks very similar (details are below). It fails non-deterministically (I mean
rexecuted executor does the work, additionally, the most oftent first trial of executor pass). The main symptom is about hanging of spark executor (every time at the same place of execution).
It relates to different spark operations, like count, write, sortBy and so on. From point of view spark-events, this executor is in scheduled state (however in fact, it is in RUNNING state because
logs points of executor and node manager points it). I did not attached logs of YARN Resource manager because it does not matter here (not impact from what I have seen).
driver log:
22/05/20 01:53:29 INFO [dispatcher-CoarseGrainedScheduler] scheduler.TaskSetManager: Starting task 12.0 in stage 2.0 (TID 13, host22.local, executor 15, partition 12, RACK_LOCAL, 7878 bytes)
[...]
22/05/20 02:04:01 WARN [dispatcher-event-loop-1] spark.HeartbeatReceiver: Removing executor 15 with no recent heartbeats: 645076 ms exceeds timeout 600000 ms
22/05/20 02:04:02 INFO [kill-executor-thread] cluster.YarnClusterSchedulerBackend: Requesting to kill executor(s) 15
22/05/20 02:04:02 INFO [kill-executor-thread] cluster.YarnClusterSchedulerBackend: Actual list of executor(s) to be killed is 15
22/05/20 02:04:03 INFO [dispatcher-event-loop-0] yarn.ApplicationMaster$AMEndpoint: Driver requested to kill executor(s) 15.
22/05/20 02:04:03 ERROR [dispatcher-CoarseGrainedScheduler] cluster.YarnClusterScheduler: Lost executor 15 on host22.local: Executor heartbeat timed out after 645076 ms
22/05/20 02:04:03 WARN [dispatcher-CoarseGrainedScheduler] scheduler.TaskSetManager: Lost task 12.0 in stage 2.0 (TID 13, host22.local, executor 15): ExecutorLostFailure (executor 15 exited caused by one of the running tasks) Reason: Executor heartbeat timed out after 645076 ms
executor log:
22/05/20 01:53:15 INFO [main] memory.MemoryStore: MemoryStore started with capacity 3.3 GiB
22/05/20 01:53:15 INFO [dispatcher-Executor] executor.YarnCoarseGrainedExecutorBackend: Connecting to driver: spark://CoarseGrainedScheduler@host04.local:38808
22/05/20 01:53:16 INFO [dispatcher-Executor] resource.ResourceUtils: ==============================================================
22/05/20 01:53:16 INFO [dispatcher-Executor] resource.ResourceUtils: Resources for spark.executor:
22/05/20 01:53:16 INFO [dispatcher-Executor] resource.ResourceUtils: ==============================================================
22/05/20 01:53:16 INFO [dispatcher-Executor] executor.YarnCoarseGrainedExecutorBackend: Successfully registered with driver
22/05/20 01:53:16 INFO [dispatcher-Executor] executor.Executor: Starting executor ID 15 on host host22.local
22/05/20 01:53:16 INFO [dispatcher-Executor] util.Utils: Successfully started service 'org.apache.spark.network.netty.NettyBlockTransferService' on port 43025.
22/05/20 01:53:16 INFO [dispatcher-Executor] netty.NettyBlockTransferService: Server created on host22.local:43025
22/05/20 01:53:16 INFO [dispatcher-Executor] storage.BlockManager: Using org.apache.spark.storage.RandomBlockReplicationPolicy for block replication policy
22/05/20 01:53:16 INFO [dispatcher-Executor] storage.BlockManagerMaster: Registering BlockManager BlockManagerId(15, host22.local, 43025, None)
22/05/20 01:53:16 INFO [dispatcher-Executor] storage.BlockManagerMaster: Registered BlockManager BlockManagerId(15, host22.local, 43025, None)
22/05/20 01:53:16 INFO [dispatcher-Executor] storage.BlockManager: Initialized BlockManager: BlockManagerId(15, host22.local, 43025, None)
22/05/20 01:53:29 INFO [dispatcher-Executor] executor.YarnCoarseGrainedExecutorBackend: Got assigned task 13
22/05/20 01:53:29 INFO [Executor task launch worker for task 13] executor.Executor: Running task 12.0 in stage 2.0 (TID 13)
22/05/20 01:53:29 INFO [Executor task launch worker for task 13] broadcast.TorrentBroadcast: Started reading broadcast variable 3 with 1 pieces (estimated total size 4.0 MiB)
22/05/20 01:53:29 INFO [Executor task launch worker for task 13] client.TransportClientFactory: Successfully created connection to host04.local/10.242.3.104:36574 after 3 ms (0 ms spent in bootstraps)
22/05/20 01:53:29 INFO [Executor task launch worker for task 13] memory.MemoryStore: Block broadcast_3_piece0 stored as bytes in memory (estimated size 6.9 KiB, free 3.3 GiB)
22/05/20 01:53:29 INFO [Executor task launch worker for task 13] broadcast.TorrentBroadcast: Reading broadcast variable 3 took 180 ms
22/05/20 01:53:30 INFO [Executor task launch worker for task 13] memory.MemoryStore: Block broadcast_3 stored as values in memory (estimated size 14.6 KiB, free 3.3 GiB)
22/05/20 01:53:31 INFO [Executor task launch worker for task 13] codegen.CodeGenerator: Code generated in 272.89621 ms
22/05/20 01:53:31 INFO [Executor task launch worker for task 13] datasources.FileScanRDD: Reading File path: hdfs:///some_parquet/
train/train/part-00011-802b056c-135b-43b1-815e-c5f81641f6d3.snappy.parquet, range: 0-170308, partition values: [empty row]
22/05/20 01:53:31 INFO [Executor task launch worker for task 13] broadcast.TorrentBroadcast: Started reading broadcast variable 2 with 1 pieces (estimated total size 4.0 MiB)
22/05/20 01:53:31 INFO [Executor task launch worker for task 13] memory.MemoryStore: Block broadcast_2_piece0 stored as bytes in memory (estimated size 53.2 KiB, free 3.3 GiB)
22/05/20 01:53:31 INFO [Executor task launch worker for task 13] broadcast.TorrentBroadcast: Reading broadcast variable 2 took 15 ms
22/05/20 01:53:31 INFO [Executor task launch worker for task 13] memory.MemoryStore: Block broadcast_2 stored as values in memory (estimated size 806.4 KiB, free 3.3 GiB)
22/05/20 02:04:03 INFO [dispatcher-Executor] executor.YarnCoarseGrainedExecutorBackend: Driver commanded a shutdown
22/05/20 02:04:04 ERROR [SIGTERM handler] executor.CoarseGrainedExecutorBackend: RECEIVED SIGNAL TERM
22/05/20 02:04:04 INFO [shutdown-hook-0] storage.DiskBlockManager: Shutdown hook called
node-manager.log
2022-05-20 02:04:04,659 INFO [NM ContainerManager dispatcher] org.apache.hadoop.yarn.server.nodemanager.containermanager.container.ContainerImpl: Container container_e68_1650799236617_5659_01_000016 transitioned from RUNNING to KILLING
2022-05-20 02:04:04,659 INFO [ContainersLauncher #139019] org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.ContainerCleanup: Cleaning up container container_e68_1650799236617_5659_01_000016
2022-05-20 02:04:04,668 WARN [ContainersLauncher #139014] org.apache.hadoop.yarn.server.nodemanager.DefaultContainerExecutor: Exit code from container container_e68_1650799236617_5659_01_000016 is : 143
2022-05-20 02:04:04,671 INFO [NM ContainerManager dispatcher] org.apache.hadoop.yarn.server.nodemanager.containermanager.container.ContainerImpl: Container container_e68_1650799236617_5659_01_000016 transitioned from KILLING to CONTAINER_CLEANEDUP_AFTER_KILL
2022-05-20 02:04:04,671 INFO [DeletionService #0] org.apache.hadoop.yarn.server.nodemanager.DefaultContainerExecutor: Deleting absolute path : /opt/sa/hdfs/nm-local-dir/usercache/packer/appcache/application_1650799236617_5659/container_e68_1650799236617_5659_01_000016
2022-05-20 02:04:04,671 INFO [NM ContainerManager dispatcher] org.apache.hadoop.yarn.server.nodemanager.NMAuditLogger: USER=packer OPERATION=Container Finished - Killed TARGET=ContainerImpl RESULT=SUCCESS APPID=application_1650799236617_5659 CONTAINERID=container_e68_1650799236617_5659_01_000016
2022-05-20 02:04:04,674 INFO [NM ContainerManager dispatcher] org.apache.hadoop.yarn.server.nodemanager.containermanager.container.ContainerImpl: Container container_e68_1650799236617_5659_01_000016 transitioned from CONTAINER_CLEANEDUP_AFTER_KILL to DONE
2022-05-20 02:04:04,674 INFO [NM ContainerManager dispatcher] org.apache.hadoop.yarn.server.nodemanager.containermanager.application.ApplicationImpl: Removing container_e68_1650799236617_5659_01_000016 from application application_1650799236617_5659
2022-05-20 02:04:04,674 INFO [NM ContainerManager dispatcher] org.apache.hadoop.yarn.server.nodemanager.containermanager.monitor.ContainersMonitorImpl: Stopping resource-monitoring for container_e68_1650799236617_5659_01_000016
2022-05-20 02:04:04,674 INFO [NM ContainerManager dispatcher] org.apache.hadoop.yarn.server.nodemanager.containermanager.logaggregation.AppLogAggregatorImpl: Considering container container_e68_1650799236617_5659_01_000016 for log-aggregation
2022-05-20 02:04:04,674 INFO [NM ContainerManager dispatcher] org.apache.hadoop.yarn.server.nodemanager.containermanager.AuxServices: Got event CONTAINER_STOP for appId application_1650799236617_5659
I know that 143 exit code does relate to memory issues, however no proof for that in executor logs (no OOM Error). Additionaly, now information about OOM in syslog. I have no idea who and when kills
my executor container. Have you and idea how to investigate/debug it? Why executor/spark app hang and does not send heartbeat to driver?