Dear Spark experts, I appreciate you can look into my problem and give me
some help and suggestions here... Thank you!
I have a simple Spark application to parse and analyze the log, and I can
run it on my hadoop yarn cluster. The problem with me is that I find it
runs quite slow on the cluster, even slower than running it just on a
single Spark machine.
This is my application sketch:
1) read in the log file and use mapToPair to transform the raw logs to my
Object - Tuple2<String, LogEntry> I use a string as key so later I will
aggregate by the key
2) persist the RDD transformed from step 1 and let me call it logObjects
3) use aggregateByKey to to calculate the sum, avg value for each key. the
reason I use aggregateByKey instead of reduce by key is the output Object
is different
4) persist the RDD from step 3, let me call it aggregatedObjects.
5) run several takeOrdered to get top X values that I'm interested in
What suprised me is that even with the persits (MEMORY_ONLY_SER) for two
major RDDs I'm manipulating later, the process speed is not improved. It's
even slower than not persist them... Any idea on that? I logged some date
to the stdout and find the two major actions take more than 1 minutes. It's
just 1GB log though...
Another problem I'm seeing is it seems just use two of my DataNode in my
Hadoop Yarn cluster, but actually I have three. Any configuration here that
matters?
I attached the syserr output here, please help me to analyze it and suggest
where can I improve the speed. Thank you so much!
(See attached file: applicationLog.txt)
Best Regards
--------------------------------------------
Yi Ming Huang(黄毅铭)
ICS Performance
IBM Collaboration Solutions, China Development Lab, Shanghai
huang...@cn.ibm.com (86-21)60922771
Addr: 5F, Building 10, No 399, Keyuan Road, Zhangjiang High Tech Park
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in
[jar:file:/tmp/hadoop-root/nm-local-dir/usercache/root/filecache/17/spark-assembly-1.2.0-hadoop2.4.0.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in
[jar:file:/opt/hadoop-2.4.1/share/hadoop/common/lib/slf4j-log4j12-1.7.5.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]
15/03/19 21:13:46 INFO yarn.ApplicationMaster: Registered signal handlers for
[TERM, HUP, INT]
15/03/19 21:13:47 WARN util.NativeCodeLoader: Unable to load native-hadoop
library for your platform... using builtin-java classes where applicable
15/03/19 21:13:47 INFO yarn.ApplicationMaster: ApplicationAttemptId:
appattempt_1426685857620_0005_000001
15/03/19 21:13:48 INFO spark.SecurityManager: Changing view acls to: root
15/03/19 21:13:48 INFO spark.SecurityManager: Changing modify acls to: root
15/03/19 21:13:48 INFO spark.SecurityManager: SecurityManager: authentication
disabled; ui acls disabled; users with view permissions: Set(root); users with
modify permissions: Set(root)
15/03/19 21:13:48 INFO yarn.ApplicationMaster: Starting the user JAR in a
separate Thread
15/03/19 21:13:48 INFO yarn.ApplicationMaster: Waiting for spark context
initialization
15/03/19 21:13:48 INFO yarn.ApplicationMaster: Waiting for spark context
initialization ... 0
15/03/19 21:13:48 INFO spark.SecurityManager: Changing view acls to: root
15/03/19 21:13:48 INFO spark.SecurityManager: Changing modify acls to: root
15/03/19 21:13:48 INFO spark.SecurityManager: SecurityManager: authentication
disabled; ui acls disabled; users with view permissions: Set(root); users with
modify permissions: Set(root)
15/03/19 21:13:48 INFO slf4j.Slf4jLogger: Slf4jLogger started
15/03/19 21:13:48 INFO Remoting: Starting remoting
15/03/19 21:13:48 INFO Remoting: Remoting started; listening on addresses
:[akka.tcp://sparkDriver@datanode03:42687]
15/03/19 21:13:48 INFO util.Utils: Successfully started service 'sparkDriver'
on port 42687.
15/03/19 21:13:48 INFO spark.SparkEnv: Registering MapOutputTracker
15/03/19 21:13:48 INFO spark.SparkEnv: Registering BlockManagerMaster
15/03/19 21:13:48 INFO storage.DiskBlockManager: Created local directory at
/tmp/hadoop-root/nm-local-dir/usercache/root/appcache/application_1426685857620_0005/spark-local-20150319211348-756f
15/03/19 21:13:48 INFO storage.MemoryStore: MemoryStore started with capacity
257.8 MB
15/03/19 21:13:48 INFO spark.HttpFileServer: HTTP File server directory is
/tmp/hadoop-root/nm-local-dir/usercache/root/appcache/application_1426685857620_0005/container_1426685857620_0005_01_000001/tmp/spark-8288d778-2bca-4afa-a805-cb3807c40f9f
15/03/19 21:13:48 INFO spark.HttpServer: Starting HTTP Server
15/03/19 21:13:49 INFO server.Server: jetty-8.y.z-SNAPSHOT
15/03/19 21:13:49 INFO server.AbstractConnector: Started
SocketConnector@0.0.0.0:54693
15/03/19 21:13:49 INFO util.Utils: Successfully started service 'HTTP file
server' on port 54693.
15/03/19 21:13:49 INFO ui.JettyUtils: Adding filter:
org.apache.hadoop.yarn.server.webproxy.amfilter.AmIpFilter
15/03/19 21:13:49 INFO server.Server: jetty-8.y.z-SNAPSHOT
15/03/19 21:13:49 INFO server.AbstractConnector: Started
SelectChannelConnector@0.0.0.0:59140
15/03/19 21:13:49 INFO util.Utils: Successfully started service 'SparkUI' on
port 59140.
15/03/19 21:13:49 INFO ui.SparkUI: Started SparkUI at http://datanode03:59140
15/03/19 21:13:49 INFO cluster.YarnClusterScheduler: Created
YarnClusterScheduler
15/03/19 21:13:49 INFO netty.NettyBlockTransferService: Server created on 59571
15/03/19 21:13:49 INFO storage.BlockManagerMaster: Trying to register
BlockManager
15/03/19 21:13:49 INFO storage.BlockManagerMasterActor: Registering block
manager datanode03:59571 with 257.8 MB RAM, BlockManagerId(<driver>,
datanode03, 59571)
15/03/19 21:13:49 INFO storage.BlockManagerMaster: Registered BlockManager
15/03/19 21:13:49 INFO client.RMProxy: Connecting to ResourceManager at
namenode/10.10.10.150:8030
15/03/19 21:13:49 INFO yarn.YarnRMClientImpl: Registering the ApplicationMaster
15/03/19 21:13:49 INFO yarn.YarnAllocationHandler: Will allocate 2 executor
containers, each with 1408 MB memory including 384 MB overhead
15/03/19 21:13:49 INFO yarn.YarnAllocationHandler: Container request (host:
Any, priority: 1, capability: <memory:1408, vCores:1>
15/03/19 21:13:49 INFO yarn.YarnAllocationHandler: Container request (host:
Any, priority: 1, capability: <memory:1408, vCores:1>
15/03/19 21:13:49 INFO yarn.ApplicationMaster: Started progress reporter thread
- sleep time : 5000
15/03/19 21:13:54 INFO impl.AMRMClientImpl: Received new token for :
datanode01:38456
15/03/19 21:13:54 INFO impl.AMRMClientImpl: Received new token for :
datanode03:56219
15/03/19 21:13:54 INFO util.RackResolver: Resolved datanode01 to /default-rack
15/03/19 21:13:54 INFO util.RackResolver: Resolved datanode03 to /default-rack
15/03/19 21:13:54 INFO yarn.YarnAllocationHandler: Launching container
container_1426685857620_0005_01_000002 for on host datanode01
15/03/19 21:13:54 INFO yarn.YarnAllocationHandler: Launching ExecutorRunnable.
driverUrl: akka.tcp://sparkDriver@datanode03:42687/user/CoarseGrainedScheduler,
executorHostname: datanode01
15/03/19 21:13:54 INFO yarn.YarnAllocationHandler: Launching container
container_1426685857620_0005_01_000003 for on host datanode03
15/03/19 21:13:54 INFO yarn.ExecutorRunnable: Starting Executor Container
15/03/19 21:13:54 INFO yarn.YarnAllocationHandler: Launching ExecutorRunnable.
driverUrl: akka.tcp://sparkDriver@datanode03:42687/user/CoarseGrainedScheduler,
executorHostname: datanode03
15/03/19 21:13:54 INFO yarn.ExecutorRunnable: Starting Executor Container
15/03/19 21:13:54 INFO impl.ContainerManagementProtocolProxy:
yarn.client.max-nodemanagers-proxies : 500
15/03/19 21:13:54 INFO impl.ContainerManagementProtocolProxy:
yarn.client.max-nodemanagers-proxies : 500
15/03/19 21:13:54 INFO yarn.ExecutorRunnable: Setting up ContainerLaunchContext
15/03/19 21:13:54 INFO yarn.ExecutorRunnable: Setting up ContainerLaunchContext
15/03/19 21:13:54 INFO yarn.ExecutorRunnable: Preparing Local resources
15/03/19 21:13:54 INFO yarn.ExecutorRunnable: Preparing Local resources
15/03/19 21:13:54 INFO yarn.ExecutorRunnable: Prepared Local resources
Map(__app__.jar -> resource { scheme: "hdfs" host: "namenode" port: 9000 file:
"/user/root/.sparkStaging/application_1426685857620_0005/MySpark.jar" } size:
20124 timestamp: 1426770824518 type: FILE visibility: PRIVATE, __spark__.jar ->
resource { scheme: "hdfs" host: "namenode" port: 9000 file:
"/user/root/.sparkStaging/application_1426685857620_0005/spark-assembly-1.2.0-hadoop2.4.0.jar"
} size: 148772423 timestamp: 1426770824422 type: FILE visibility: PRIVATE)
15/03/19 21:13:54 INFO yarn.ExecutorRunnable: Prepared Local resources
Map(__app__.jar -> resource { scheme: "hdfs" host: "namenode" port: 9000 file:
"/user/root/.sparkStaging/application_1426685857620_0005/MySpark.jar" } size:
20124 timestamp: 1426770824518 type: FILE visibility: PRIVATE, __spark__.jar ->
resource { scheme: "hdfs" host: "namenode" port: 9000 file:
"/user/root/.sparkStaging/application_1426685857620_0005/spark-assembly-1.2.0-hadoop2.4.0.jar"
} size: 148772423 timestamp: 1426770824422 type: FILE visibility: PRIVATE)
15/03/19 21:13:54 INFO yarn.ExecutorRunnable: Setting up executor with
environment: Map(CLASSPATH ->
$PWD:$PWD/__spark__.jar:$HADOOP_CONF_DIR:$HADOOP_COMMON_HOME/share/hadoop/common/*:$HADOOP_COMMON_HOME/share/hadoop/common/lib/*:$HADOOP_HDFS_HOME/share/hadoop/hdfs/*:$HADOOP_HDFS_HOME/share/hadoop/hdfs/lib/*:$HADOOP_YARN_HOME/share/hadoop/yarn/*:$HADOOP_YARN_HOME/share/hadoop/yarn/lib/*:$HADOOP_MAPRED_HOME/share/hadoop/mapreduce/*:$HADOOP_MAPRED_HOME/share/hadoop/mapreduce/lib/*:$PWD/__app__.jar:$PWD/*,
SPARK_YARN_STAGING_DIR -> .sparkStaging/application_1426685857620_0005/,
SPARK_YARN_CACHE_FILES_FILE_SIZES -> 148772423,20124, SPARK_USER -> root,
SPARK_YARN_CACHE_FILES_VISIBILITIES -> PRIVATE,PRIVATE, SPARK_YARN_MODE ->
true, SPARK_YARN_CACHE_FILES_TIME_STAMPS -> 1426770824422,1426770824518,
SPARK_YARN_CACHE_FILES ->
hdfs://namenode:9000/user/root/.sparkStaging/application_1426685857620_0005/spark-assembly-1.2.0-hadoop2.4.0.jar#__spark__.jar,hdfs://namenode:9000/user/root/.sparkStaging/application_1426685857620_0005/MySpark.jar#__app__.jar)
15/03/19 21:13:54 INFO yarn.ExecutorRunnable: Setting up executor with
environment: Map(CLASSPATH ->
$PWD:$PWD/__spark__.jar:$HADOOP_CONF_DIR:$HADOOP_COMMON_HOME/share/hadoop/common/*:$HADOOP_COMMON_HOME/share/hadoop/common/lib/*:$HADOOP_HDFS_HOME/share/hadoop/hdfs/*:$HADOOP_HDFS_HOME/share/hadoop/hdfs/lib/*:$HADOOP_YARN_HOME/share/hadoop/yarn/*:$HADOOP_YARN_HOME/share/hadoop/yarn/lib/*:$HADOOP_MAPRED_HOME/share/hadoop/mapreduce/*:$HADOOP_MAPRED_HOME/share/hadoop/mapreduce/lib/*:$PWD/__app__.jar:$PWD/*,
SPARK_YARN_STAGING_DIR -> .sparkStaging/application_1426685857620_0005/,
SPARK_YARN_CACHE_FILES_FILE_SIZES -> 148772423,20124, SPARK_USER -> root,
SPARK_YARN_CACHE_FILES_VISIBILITIES -> PRIVATE,PRIVATE, SPARK_YARN_MODE ->
true, SPARK_YARN_CACHE_FILES_TIME_STAMPS -> 1426770824422,1426770824518,
SPARK_YARN_CACHE_FILES ->
hdfs://namenode:9000/user/root/.sparkStaging/application_1426685857620_0005/spark-assembly-1.2.0-hadoop2.4.0.jar#__spark__.jar,hdfs://namenode:9000/user/root/.sparkStaging/application_1426685857620_0005/MySpark.jar#__app__.jar)
15/03/19 21:13:54 INFO yarn.ExecutorRunnable: Setting up executor with
commands: List($JAVA_HOME/bin/java, -server, -XX:OnOutOfMemoryError='kill %p',
-Xms1024m -Xmx1024m , -Djava.io.tmpdir=$PWD/tmp,
-Dspark.yarn.app.container.log.dir=<LOG_DIR>,
org.apache.spark.executor.CoarseGrainedExecutorBackend,
akka.tcp://sparkDriver@datanode03:42687/user/CoarseGrainedScheduler, 1,
datanode01, 1, application_1426685857620_0005, 1>, <LOG_DIR>/stdout, 2>,
<LOG_DIR>/stderr)
15/03/19 21:13:54 INFO yarn.ExecutorRunnable: Setting up executor with
commands: List($JAVA_HOME/bin/java, -server, -XX:OnOutOfMemoryError='kill %p',
-Xms1024m -Xmx1024m , -Djava.io.tmpdir=$PWD/tmp,
-Dspark.yarn.app.container.log.dir=<LOG_DIR>,
org.apache.spark.executor.CoarseGrainedExecutorBackend,
akka.tcp://sparkDriver@datanode03:42687/user/CoarseGrainedScheduler, 2,
datanode03, 1, application_1426685857620_0005, 1>, <LOG_DIR>/stdout, 2>,
<LOG_DIR>/stderr)
15/03/19 21:13:54 INFO impl.ContainerManagementProtocolProxy: Opening proxy :
datanode03:56219
15/03/19 21:13:54 INFO impl.ContainerManagementProtocolProxy: Opening proxy :
datanode01:38456
15/03/19 21:13:57 INFO cluster.YarnClusterSchedulerBackend: Registered
executor:
Actor[akka.tcp://sparkExecutor@datanode03:50472/user/Executor#1999788961] with
ID 2
15/03/19 21:13:57 INFO storage.BlockManagerMasterActor: Registering block
manager datanode03:59127 with 529.9 MB RAM, BlockManagerId(2, datanode03, 59127)
15/03/19 21:13:58 INFO cluster.YarnClusterSchedulerBackend: Registered
executor:
Actor[akka.tcp://sparkExecutor@datanode01:50156/user/Executor#1735717900] with
ID 1
15/03/19 21:13:58 INFO cluster.YarnClusterSchedulerBackend: SchedulerBackend is
ready for scheduling beginning after reached minRegisteredResourcesRatio: 0.8
15/03/19 21:13:58 INFO cluster.YarnClusterScheduler:
YarnClusterScheduler.postStartHook done
15/03/19 21:13:58 INFO storage.MemoryStore: ensureFreeSpace(107889) called with
curMem=0, maxMem=270375321
15/03/19 21:13:58 INFO storage.MemoryStore: Block broadcast_0 stored as values
in memory (estimated size 105.4 KB, free 257.7 MB)
15/03/19 21:13:58 INFO storage.MemoryStore: ensureFreeSpace(31616) called with
curMem=107889, maxMem=270375321
15/03/19 21:13:58 INFO storage.MemoryStore: Block broadcast_0_piece0 stored as
bytes in memory (estimated size 30.9 KB, free 257.7 MB)
15/03/19 21:13:58 INFO storage.BlockManagerInfo: Added broadcast_0_piece0 in
memory on datanode03:59571 (size: 30.9 KB, free: 257.8 MB)
15/03/19 21:13:58 INFO storage.BlockManagerMaster: Updated info of block
broadcast_0_piece0
15/03/19 21:13:58 INFO spark.SparkContext: Created broadcast 0 from textFile at
TestSparkApp.java:65
15/03/19 21:13:58 INFO mapred.FileInputFormat: Total input paths to process : 8
15/03/19 21:13:58 INFO storage.BlockManagerMasterActor: Registering block
manager datanode01:59567 with 529.9 MB RAM, BlockManagerId(1, datanode01, 59567)
15/03/19 21:13:58 INFO spark.SparkContext: Starting job: count at
TestSparkApp.java:116
15/03/19 21:13:58 INFO scheduler.DAGScheduler: Got job 0 (count at
TestSparkApp.java:116) with 16 output partitions (allowLocal=false)
15/03/19 21:13:58 INFO scheduler.DAGScheduler: Final stage: Stage 0(count at
TestSparkApp.java:116)
15/03/19 21:13:58 INFO scheduler.DAGScheduler: Parents of final stage: List()
15/03/19 21:13:58 INFO scheduler.DAGScheduler: Missing parents: List()
15/03/19 21:13:58 INFO scheduler.DAGScheduler: Submitting Stage 0
(hdfs://namenode:9000/test/files/access*.log MappedRDD[1] at textFile at
TestSparkApp.java:65), which has no missing parents
15/03/19 21:13:58 INFO storage.MemoryStore: ensureFreeSpace(2544) called with
curMem=139505, maxMem=270375321
15/03/19 21:13:58 INFO storage.MemoryStore: Block broadcast_1 stored as values
in memory (estimated size 2.5 KB, free 257.7 MB)
15/03/19 21:13:58 INFO storage.MemoryStore: ensureFreeSpace(1896) called with
curMem=142049, maxMem=270375321
15/03/19 21:13:58 INFO storage.MemoryStore: Block broadcast_1_piece0 stored as
bytes in memory (estimated size 1896.0 B, free 257.7 MB)
15/03/19 21:13:58 INFO storage.BlockManagerInfo: Added broadcast_1_piece0 in
memory on datanode03:59571 (size: 1896.0 B, free: 257.8 MB)
15/03/19 21:13:58 INFO storage.BlockManagerMaster: Updated info of block
broadcast_1_piece0
15/03/19 21:13:58 INFO spark.SparkContext: Created broadcast 1 from broadcast
at DAGScheduler.scala:838
15/03/19 21:13:58 INFO scheduler.DAGScheduler: Submitting 16 missing tasks from
Stage 0 (hdfs://namenode:9000/test/files/access*.log MappedRDD[1] at textFile
at TestSparkApp.java:65)
15/03/19 21:13:58 INFO cluster.YarnClusterScheduler: Adding task set 0.0 with
16 tasks
15/03/19 21:13:58 INFO util.RackResolver: Resolved datanode02 to /default-rack
15/03/19 21:13:58 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 0.0
(TID 0, datanode01, NODE_LOCAL, 1326 bytes)
15/03/19 21:13:58 INFO scheduler.TaskSetManager: Starting task 1.0 in stage 0.0
(TID 1, datanode03, NODE_LOCAL, 1326 bytes)
15/03/19 21:13:59 INFO storage.BlockManagerInfo: Added broadcast_1_piece0 in
memory on datanode01:59567 (size: 1896.0 B, free: 529.9 MB)
15/03/19 21:13:59 INFO storage.BlockManagerInfo: Added broadcast_1_piece0 in
memory on datanode03:59127 (size: 1896.0 B, free: 529.9 MB)
15/03/19 21:13:59 INFO storage.BlockManagerInfo: Added broadcast_0_piece0 in
memory on datanode03:59127 (size: 30.9 KB, free: 529.9 MB)
15/03/19 21:13:59 INFO storage.BlockManagerInfo: Added broadcast_0_piece0 in
memory on datanode01:59567 (size: 30.9 KB, free: 529.9 MB)
15/03/19 21:14:00 INFO scheduler.TaskSetManager: Starting task 2.0 in stage 0.0
(TID 2, datanode03, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:00 INFO scheduler.TaskSetManager: Finished task 1.0 in stage 0.0
(TID 1) in 1613 ms on datanode03 (1/16)
15/03/19 21:14:01 INFO scheduler.TaskSetManager: Starting task 3.0 in stage 0.0
(TID 3, datanode01, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:01 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 0.0
(TID 0) in 2536 ms on datanode01 (2/16)
15/03/19 21:14:01 INFO scheduler.TaskSetManager: Starting task 4.0 in stage 0.0
(TID 4, datanode01, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:01 INFO scheduler.TaskSetManager: Finished task 3.0 in stage 0.0
(TID 3) in 225 ms on datanode01 (3/16)
15/03/19 21:14:01 INFO scheduler.TaskSetManager: Starting task 5.0 in stage 0.0
(TID 5, datanode03, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:01 INFO scheduler.TaskSetManager: Finished task 2.0 in stage 0.0
(TID 2) in 1163 ms on datanode03 (4/16)
15/03/19 21:14:01 INFO scheduler.TaskSetManager: Starting task 6.0 in stage 0.0
(TID 6, datanode03, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:01 INFO scheduler.TaskSetManager: Finished task 5.0 in stage 0.0
(TID 5) in 204 ms on datanode03 (5/16)
15/03/19 21:14:02 INFO scheduler.TaskSetManager: Starting task 7.0 in stage 0.0
(TID 7, datanode01, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:02 INFO scheduler.TaskSetManager: Finished task 4.0 in stage 0.0
(TID 4) in 1096 ms on datanode01 (6/16)
15/03/19 21:14:02 INFO scheduler.TaskSetManager: Starting task 8.0 in stage 0.0
(TID 8, datanode01, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:02 INFO scheduler.TaskSetManager: Finished task 7.0 in stage 0.0
(TID 7) in 219 ms on datanode01 (7/16)
15/03/19 21:14:03 INFO scheduler.TaskSetManager: Starting task 9.0 in stage 0.0
(TID 9, datanode03, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:03 INFO scheduler.TaskSetManager: Finished task 6.0 in stage 0.0
(TID 6) in 1113 ms on datanode03 (8/16)
15/03/19 21:14:03 INFO scheduler.TaskSetManager: Starting task 10.0 in stage
0.0 (TID 10, datanode03, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:03 INFO scheduler.TaskSetManager: Finished task 9.0 in stage 0.0
(TID 9) in 198 ms on datanode03 (9/16)
15/03/19 21:14:04 INFO scheduler.TaskSetManager: Starting task 11.0 in stage
0.0 (TID 11, datanode01, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:04 INFO scheduler.TaskSetManager: Finished task 8.0 in stage 0.0
(TID 8) in 1028 ms on datanode01 (10/16)
15/03/19 21:14:04 INFO scheduler.TaskSetManager: Starting task 12.0 in stage
0.0 (TID 12, datanode01, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:04 INFO scheduler.TaskSetManager: Finished task 11.0 in stage
0.0 (TID 11) in 200 ms on datanode01 (11/16)
15/03/19 21:14:04 INFO scheduler.TaskSetManager: Starting task 13.0 in stage
0.0 (TID 13, datanode03, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:04 INFO scheduler.TaskSetManager: Finished task 10.0 in stage
0.0 (TID 10) in 1016 ms on datanode03 (12/16)
15/03/19 21:14:04 INFO scheduler.TaskSetManager: Starting task 14.0 in stage
0.0 (TID 14, datanode03, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:04 INFO scheduler.TaskSetManager: Finished task 13.0 in stage
0.0 (TID 13) in 195 ms on datanode03 (13/16)
15/03/19 21:14:05 INFO scheduler.TaskSetManager: Starting task 15.0 in stage
0.0 (TID 15, datanode01, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:05 INFO scheduler.TaskSetManager: Finished task 12.0 in stage
0.0 (TID 12) in 1023 ms on datanode01 (14/16)
15/03/19 21:14:05 INFO scheduler.TaskSetManager: Finished task 14.0 in stage
0.0 (TID 14) in 1011 ms on datanode03 (15/16)
15/03/19 21:14:05 INFO scheduler.TaskSetManager: Finished task 15.0 in stage
0.0 (TID 15) in 196 ms on datanode01 (16/16)
15/03/19 21:14:05 INFO scheduler.DAGScheduler: Stage 0 (count at
TestSparkApp.java:116) finished in 6.509 s
15/03/19 21:14:05 INFO cluster.YarnClusterScheduler: Removed TaskSet 0.0, whose
tasks have all completed, from pool
15/03/19 21:14:05 INFO scheduler.DAGScheduler: Job 0 finished: count at
TestSparkApp.java:116, took 6.596501 s
15/03/19 21:14:05 INFO spark.SparkContext: Starting job: count at
TestSparkApp.java:116
15/03/19 21:14:05 INFO scheduler.DAGScheduler: Got job 1 (count at
TestSparkApp.java:116) with 16 output partitions (allowLocal=false)
15/03/19 21:14:05 INFO scheduler.DAGScheduler: Final stage: Stage 1(count at
TestSparkApp.java:116)
15/03/19 21:14:05 INFO scheduler.DAGScheduler: Parents of final stage: List()
15/03/19 21:14:05 INFO scheduler.DAGScheduler: Missing parents: List()
15/03/19 21:14:05 INFO scheduler.DAGScheduler: Submitting Stage 1 (MappedRDD[2]
at mapToPair at TestSparkApp.java:70), which has no missing parents
15/03/19 21:14:05 INFO storage.MemoryStore: ensureFreeSpace(4672) called with
curMem=143945, maxMem=270375321
15/03/19 21:14:05 INFO storage.MemoryStore: Block broadcast_2 stored as values
in memory (estimated size 4.6 KB, free 257.7 MB)
15/03/19 21:14:05 INFO storage.MemoryStore: ensureFreeSpace(3033) called with
curMem=148617, maxMem=270375321
15/03/19 21:14:05 INFO storage.MemoryStore: Block broadcast_2_piece0 stored as
bytes in memory (estimated size 3.0 KB, free 257.7 MB)
15/03/19 21:14:05 INFO storage.BlockManagerInfo: Added broadcast_2_piece0 in
memory on datanode03:59571 (size: 3.0 KB, free: 257.8 MB)
15/03/19 21:14:05 INFO storage.BlockManagerMaster: Updated info of block
broadcast_2_piece0
15/03/19 21:14:05 INFO spark.SparkContext: Created broadcast 2 from broadcast
at DAGScheduler.scala:838
15/03/19 21:14:05 INFO scheduler.DAGScheduler: Submitting 16 missing tasks from
Stage 1 (MappedRDD[2] at mapToPair at TestSparkApp.java:70)
15/03/19 21:14:05 INFO cluster.YarnClusterScheduler: Adding task set 1.0 with
16 tasks
15/03/19 21:14:05 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 1.0
(TID 16, datanode01, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:05 INFO scheduler.TaskSetManager: Starting task 1.0 in stage 1.0
(TID 17, datanode03, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:05 INFO storage.BlockManagerInfo: Added broadcast_2_piece0 in
memory on datanode03:59127 (size: 3.0 KB, free: 529.9 MB)
15/03/19 21:14:05 INFO storage.BlockManagerInfo: Added broadcast_2_piece0 in
memory on datanode01:59567 (size: 3.0 KB, free: 529.9 MB)
15/03/19 21:14:13 INFO storage.BlockManagerInfo: Added rdd_2_1 in memory on
datanode03:59127 (size: 140.1 MB, free: 389.8 MB)
15/03/19 21:14:13 INFO scheduler.TaskSetManager: Starting task 2.0 in stage 1.0
(TID 18, datanode03, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:13 INFO scheduler.TaskSetManager: Finished task 1.0 in stage 1.0
(TID 17) in 8024 ms on datanode03 (1/16)
15/03/19 21:14:22 INFO scheduler.TaskSetManager: Starting task 3.0 in stage 1.0
(TID 19, datanode01, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:22 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 1.0
(TID 16) in 17188 ms on datanode01 (2/16)
15/03/19 21:14:30 INFO storage.BlockManagerInfo: Added rdd_2_3 in memory on
datanode01:59567 (size: 140.5 MB, free: 389.4 MB)
15/03/19 21:14:30 INFO scheduler.TaskSetManager: Starting task 4.0 in stage 1.0
(TID 20, datanode01, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:30 INFO scheduler.TaskSetManager: Finished task 3.0 in stage 1.0
(TID 19) in 7576 ms on datanode01 (3/16)
15/03/19 21:14:30 INFO scheduler.TaskSetManager: Starting task 5.0 in stage 1.0
(TID 21, datanode03, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:30 INFO scheduler.TaskSetManager: Finished task 2.0 in stage 1.0
(TID 18) in 16923 ms on datanode03 (4/16)
15/03/19 21:14:33 INFO scheduler.TaskSetManager: Starting task 6.0 in stage 1.0
(TID 22, datanode03, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:33 INFO scheduler.TaskSetManager: Finished task 5.0 in stage 1.0
(TID 21) in 3307 ms on datanode03 (5/16)
15/03/19 21:14:46 INFO scheduler.TaskSetManager: Starting task 7.0 in stage 1.0
(TID 23, datanode01, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:46 INFO scheduler.TaskSetManager: Finished task 4.0 in stage 1.0
(TID 20) in 15826 ms on datanode01 (6/16)
15/03/19 21:14:49 INFO scheduler.TaskSetManager: Starting task 8.0 in stage 1.0
(TID 24, datanode01, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:49 INFO scheduler.TaskSetManager: Finished task 7.0 in stage 1.0
(TID 23) in 3161 ms on datanode01 (7/16)
15/03/19 21:14:49 INFO scheduler.TaskSetManager: Starting task 9.0 in stage 1.0
(TID 25, datanode03, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:49 INFO scheduler.TaskSetManager: Finished task 6.0 in stage 1.0
(TID 22) in 16181 ms on datanode03 (8/16)
15/03/19 21:14:53 INFO scheduler.TaskSetManager: Starting task 10.0 in stage
1.0 (TID 26, datanode03, NODE_LOCAL, 1326 bytes)
15/03/19 21:14:53 INFO scheduler.TaskSetManager: Finished task 9.0 in stage 1.0
(TID 25) in 3226 ms on datanode03 (9/16)
15/03/19 21:15:04 INFO scheduler.TaskSetManager: Starting task 11.0 in stage
1.0 (TID 27, datanode01, NODE_LOCAL, 1326 bytes)
15/03/19 21:15:04 INFO scheduler.TaskSetManager: Finished task 8.0 in stage 1.0
(TID 24) in 15400 ms on datanode01 (10/16)
15/03/19 21:15:07 INFO scheduler.TaskSetManager: Starting task 12.0 in stage
1.0 (TID 28, datanode01, NODE_LOCAL, 1326 bytes)
15/03/19 21:15:07 INFO scheduler.TaskSetManager: Finished task 11.0 in stage
1.0 (TID 27) in 3157 ms on datanode01 (11/16)
15/03/19 21:15:09 INFO scheduler.TaskSetManager: Starting task 13.0 in stage
1.0 (TID 29, datanode03, NODE_LOCAL, 1326 bytes)
15/03/19 21:15:09 INFO scheduler.TaskSetManager: Finished task 10.0 in stage
1.0 (TID 26) in 16103 ms on datanode03 (12/16)
15/03/19 21:15:12 INFO scheduler.TaskSetManager: Starting task 14.0 in stage
1.0 (TID 30, datanode03, NODE_LOCAL, 1326 bytes)
15/03/19 21:15:12 INFO scheduler.TaskSetManager: Finished task 13.0 in stage
1.0 (TID 29) in 3251 ms on datanode03 (13/16)
15/03/19 21:15:23 INFO scheduler.TaskSetManager: Starting task 15.0 in stage
1.0 (TID 31, datanode01, NODE_LOCAL, 1326 bytes)
15/03/19 21:15:23 INFO scheduler.TaskSetManager: Finished task 12.0 in stage
1.0 (TID 28) in 15452 ms on datanode01 (14/16)
15/03/19 21:15:26 INFO scheduler.TaskSetManager: Finished task 15.0 in stage
1.0 (TID 31) in 3121 ms on datanode01 (15/16)
15/03/19 21:15:28 INFO scheduler.TaskSetManager: Finished task 14.0 in stage
1.0 (TID 30) in 16096 ms on datanode03 (16/16)
15/03/19 21:15:28 INFO scheduler.DAGScheduler: Stage 1 (count at
TestSparkApp.java:116) finished in 83.101 s
15/03/19 21:15:28 INFO cluster.YarnClusterScheduler: Removed TaskSet 1.0, whose
tasks have all completed, from pool
15/03/19 21:15:28 INFO scheduler.DAGScheduler: Job 1 finished: count at
TestSparkApp.java:116, took 83.125367 s
15/03/19 21:15:28 INFO spark.SparkContext: Starting job: count at
TestSparkApp.java:161
15/03/19 21:15:28 INFO scheduler.DAGScheduler: Registering RDD 2 (mapToPair at
TestSparkApp.java:70)
15/03/19 21:15:28 INFO scheduler.DAGScheduler: Got job 2 (count at
TestSparkApp.java:161) with 16 output partitions (allowLocal=false)
15/03/19 21:15:28 INFO scheduler.DAGScheduler: Final stage: Stage 3(count at
TestSparkApp.java:161)
15/03/19 21:15:28 INFO scheduler.DAGScheduler: Parents of final stage:
List(Stage 2)
15/03/19 21:15:28 INFO scheduler.DAGScheduler: Missing parents: List(Stage 2)
15/03/19 21:15:28 INFO scheduler.DAGScheduler: Submitting Stage 2 (MappedRDD[2]
at mapToPair at TestSparkApp.java:70), which has no missing parents
15/03/19 21:15:28 INFO storage.MemoryStore: ensureFreeSpace(6624) called with
curMem=151650, maxMem=270375321
15/03/19 21:15:28 INFO storage.MemoryStore: Block broadcast_3 stored as values
in memory (estimated size 6.5 KB, free 257.7 MB)
15/03/19 21:15:28 INFO storage.MemoryStore: ensureFreeSpace(4407) called with
curMem=158274, maxMem=270375321
15/03/19 21:15:28 INFO storage.MemoryStore: Block broadcast_3_piece0 stored as
bytes in memory (estimated size 4.3 KB, free 257.7 MB)
15/03/19 21:15:28 INFO storage.BlockManagerInfo: Added broadcast_3_piece0 in
memory on datanode03:59571 (size: 4.3 KB, free: 257.8 MB)
15/03/19 21:15:28 INFO storage.BlockManagerMaster: Updated info of block
broadcast_3_piece0
15/03/19 21:15:28 INFO spark.SparkContext: Created broadcast 3 from broadcast
at DAGScheduler.scala:838
15/03/19 21:15:28 INFO scheduler.DAGScheduler: Submitting 16 missing tasks from
Stage 2 (MappedRDD[2] at mapToPair at TestSparkApp.java:70)
15/03/19 21:15:28 INFO cluster.YarnClusterScheduler: Adding task set 2.0 with
16 tasks
15/03/19 21:15:28 INFO scheduler.TaskSetManager: Starting task 1.0 in stage 2.0
(TID 32, datanode03, PROCESS_LOCAL, 1315 bytes)
15/03/19 21:15:28 INFO scheduler.TaskSetManager: Starting task 3.0 in stage 2.0
(TID 33, datanode01, PROCESS_LOCAL, 1315 bytes)
15/03/19 21:15:28 INFO storage.BlockManagerInfo: Added broadcast_3_piece0 in
memory on datanode03:59127 (size: 4.3 KB, free: 389.8 MB)
15/03/19 21:15:28 INFO storage.BlockManagerInfo: Added broadcast_3_piece0 in
memory on datanode01:59567 (size: 4.3 KB, free: 389.4 MB)
15/03/19 21:15:32 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 2.0
(TID 34, datanode01, NODE_LOCAL, 1315 bytes)
15/03/19 21:15:32 INFO scheduler.TaskSetManager: Finished task 3.0 in stage 2.0
(TID 33) in 4071 ms on datanode01 (1/16)
15/03/19 21:15:32 INFO scheduler.TaskSetManager: Starting task 2.0 in stage 2.0
(TID 35, datanode03, NODE_LOCAL, 1315 bytes)
15/03/19 21:15:32 INFO scheduler.TaskSetManager: Finished task 1.0 in stage 2.0
(TID 32) in 4213 ms on datanode03 (2/16)
15/03/19 21:15:48 INFO scheduler.TaskSetManager: Starting task 4.0 in stage 2.0
(TID 36, datanode01, NODE_LOCAL, 1315 bytes)
15/03/19 21:15:48 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 2.0
(TID 34) in 15983 ms on datanode01 (3/16)
15/03/19 21:15:50 INFO scheduler.TaskSetManager: Starting task 5.0 in stage 2.0
(TID 37, datanode03, NODE_LOCAL, 1315 bytes)
15/03/19 21:15:50 INFO scheduler.TaskSetManager: Finished task 2.0 in stage 2.0
(TID 35) in 17520 ms on datanode03 (4/16)
15/03/19 21:15:53 INFO scheduler.TaskSetManager: Starting task 6.0 in stage 2.0
(TID 38, datanode03, NODE_LOCAL, 1315 bytes)
15/03/19 21:15:53 INFO scheduler.TaskSetManager: Finished task 5.0 in stage 2.0
(TID 37) in 3355 ms on datanode03 (5/16)
15/03/19 21:16:04 INFO scheduler.TaskSetManager: Starting task 7.0 in stage 2.0
(TID 39, datanode01, NODE_LOCAL, 1315 bytes)
15/03/19 21:16:04 INFO scheduler.TaskSetManager: Finished task 4.0 in stage 2.0
(TID 36) in 16225 ms on datanode01 (6/16)
15/03/19 21:16:08 INFO scheduler.TaskSetManager: Starting task 8.0 in stage 2.0
(TID 40, datanode01, NODE_LOCAL, 1315 bytes)
15/03/19 21:16:08 INFO scheduler.TaskSetManager: Finished task 7.0 in stage 2.0
(TID 39) in 3245 ms on datanode01 (7/16)
15/03/19 21:16:10 INFO scheduler.TaskSetManager: Starting task 9.0 in stage 2.0
(TID 41, datanode03, NODE_LOCAL, 1315 bytes)
15/03/19 21:16:10 INFO scheduler.TaskSetManager: Finished task 6.0 in stage 2.0
(TID 38) in 16764 ms on datanode03 (8/16)
15/03/19 21:16:13 INFO scheduler.TaskSetManager: Starting task 10.0 in stage
2.0 (TID 42, datanode03, NODE_LOCAL, 1315 bytes)
15/03/19 21:16:13 INFO scheduler.TaskSetManager: Finished task 9.0 in stage 2.0
(TID 41) in 3372 ms on datanode03 (9/16)
15/03/19 21:16:23 INFO scheduler.TaskSetManager: Starting task 11.0 in stage
2.0 (TID 43, datanode01, NODE_LOCAL, 1315 bytes)
15/03/19 21:16:23 INFO scheduler.TaskSetManager: Finished task 8.0 in stage 2.0
(TID 40) in 15801 ms on datanode01 (10/16)
15/03/19 21:16:27 INFO scheduler.TaskSetManager: Starting task 12.0 in stage
2.0 (TID 44, datanode01, NODE_LOCAL, 1315 bytes)
15/03/19 21:16:27 INFO scheduler.TaskSetManager: Finished task 11.0 in stage
2.0 (TID 43) in 3230 ms on datanode01 (11/16)
15/03/19 21:16:30 INFO scheduler.TaskSetManager: Starting task 13.0 in stage
2.0 (TID 45, datanode03, NODE_LOCAL, 1315 bytes)
15/03/19 21:16:30 INFO scheduler.TaskSetManager: Finished task 10.0 in stage
2.0 (TID 42) in 16660 ms on datanode03 (12/16)
15/03/19 21:16:33 INFO scheduler.TaskSetManager: Starting task 14.0 in stage
2.0 (TID 46, datanode03, NODE_LOCAL, 1315 bytes)
15/03/19 21:16:33 INFO scheduler.TaskSetManager: Finished task 13.0 in stage
2.0 (TID 45) in 3351 ms on datanode03 (13/16)
15/03/19 21:16:42 INFO scheduler.TaskSetManager: Starting task 15.0 in stage
2.0 (TID 47, datanode01, NODE_LOCAL, 1315 bytes)
15/03/19 21:16:42 INFO scheduler.TaskSetManager: Finished task 12.0 in stage
2.0 (TID 44) in 15768 ms on datanode01 (14/16)
15/03/19 21:16:46 INFO scheduler.TaskSetManager: Finished task 15.0 in stage
2.0 (TID 47) in 3232 ms on datanode01 (15/16)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Finished task 14.0 in stage
2.0 (TID 46) in 16741 ms on datanode03 (16/16)
15/03/19 21:16:50 INFO scheduler.DAGScheduler: Stage 2 (mapToPair at
TestSparkApp.java:70) finished in 81.968 s
15/03/19 21:16:50 INFO cluster.YarnClusterScheduler: Removed TaskSet 2.0, whose
tasks have all completed, from pool
15/03/19 21:16:50 INFO scheduler.DAGScheduler: looking for newly runnable stages
15/03/19 21:16:50 INFO scheduler.DAGScheduler: running: Set()
15/03/19 21:16:50 INFO scheduler.DAGScheduler: waiting: Set(Stage 3)
15/03/19 21:16:50 INFO scheduler.DAGScheduler: failed: Set()
15/03/19 21:16:50 INFO scheduler.DAGScheduler: Missing parents for Stage 3:
List()
15/03/19 21:16:50 INFO scheduler.DAGScheduler: Submitting Stage 3
(ShuffledRDD[3] at aggregateByKey at TestSparkApp.java:135), which is now
runnable
15/03/19 21:16:50 INFO storage.MemoryStore: ensureFreeSpace(6992) called with
curMem=162681, maxMem=270375321
15/03/19 21:16:50 INFO storage.MemoryStore: Block broadcast_4 stored as values
in memory (estimated size 6.8 KB, free 257.7 MB)
15/03/19 21:16:50 INFO storage.MemoryStore: ensureFreeSpace(4628) called with
curMem=169673, maxMem=270375321
15/03/19 21:16:50 INFO storage.MemoryStore: Block broadcast_4_piece0 stored as
bytes in memory (estimated size 4.5 KB, free 257.7 MB)
15/03/19 21:16:50 INFO storage.BlockManagerInfo: Added broadcast_4_piece0 in
memory on datanode03:59571 (size: 4.5 KB, free: 257.8 MB)
15/03/19 21:16:50 INFO storage.BlockManagerMaster: Updated info of block
broadcast_4_piece0
15/03/19 21:16:50 INFO spark.SparkContext: Created broadcast 4 from broadcast
at DAGScheduler.scala:838
15/03/19 21:16:50 INFO scheduler.DAGScheduler: Submitting 16 missing tasks from
Stage 3 (ShuffledRDD[3] at aggregateByKey at TestSparkApp.java:135)
15/03/19 21:16:50 INFO cluster.YarnClusterScheduler: Adding task set 3.0 with
16 tasks
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 3.0
(TID 48, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Starting task 1.0 in stage 3.0
(TID 49, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:50 INFO storage.BlockManagerInfo: Added broadcast_4_piece0 in
memory on datanode03:59127 (size: 4.5 KB, free: 389.8 MB)
15/03/19 21:16:50 INFO storage.BlockManagerInfo: Added broadcast_4_piece0 in
memory on datanode01:59567 (size: 4.5 KB, free: 389.4 MB)
15/03/19 21:16:50 INFO spark.MapOutputTrackerMasterActor: Asked to send map
output locations for shuffle 0 to sparkExecutor@datanode03:50472
15/03/19 21:16:50 INFO spark.MapOutputTrackerMaster: Size of output statuses
for shuffle 0 is 376 bytes
15/03/19 21:16:50 INFO spark.MapOutputTrackerMasterActor: Asked to send map
output locations for shuffle 0 to sparkExecutor@datanode01:50156
15/03/19 21:16:50 INFO storage.BlockManagerInfo: Added rdd_3_0 in memory on
datanode01:59567 (size: 32.9 KB, free: 389.3 MB)
15/03/19 21:16:50 INFO storage.BlockManagerInfo: Added rdd_3_1 in memory on
datanode03:59127 (size: 59.3 KB, free: 389.7 MB)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Starting task 2.0 in stage 3.0
(TID 50, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 3.0
(TID 48) in 130 ms on datanode01 (1/16)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Starting task 3.0 in stage 3.0
(TID 51, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Finished task 1.0 in stage 3.0
(TID 49) in 134 ms on datanode03 (2/16)
15/03/19 21:16:50 INFO storage.BlockManagerInfo: Added rdd_3_3 in memory on
datanode03:59127 (size: 34.5 KB, free: 389.7 MB)
15/03/19 21:16:50 INFO storage.BlockManagerInfo: Added rdd_3_2 in memory on
datanode01:59567 (size: 39.9 KB, free: 389.3 MB)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Starting task 4.0 in stage 3.0
(TID 52, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Finished task 2.0 in stage 3.0
(TID 50) in 66 ms on datanode01 (3/16)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Starting task 5.0 in stage 3.0
(TID 53, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Finished task 3.0 in stage 3.0
(TID 51) in 63 ms on datanode03 (4/16)
15/03/19 21:16:50 INFO storage.BlockManagerInfo: Added rdd_3_5 in memory on
datanode03:59127 (size: 40.6 KB, free: 389.7 MB)
15/03/19 21:16:50 INFO storage.BlockManagerInfo: Added rdd_3_4 in memory on
datanode01:59567 (size: 35.8 KB, free: 389.3 MB)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Starting task 6.0 in stage 3.0
(TID 54, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Finished task 5.0 in stage 3.0
(TID 53) in 52 ms on datanode03 (5/16)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Starting task 7.0 in stage 3.0
(TID 55, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Finished task 4.0 in stage 3.0
(TID 52) in 60 ms on datanode01 (6/16)
15/03/19 21:16:50 INFO storage.BlockManagerInfo: Added rdd_3_6 in memory on
datanode03:59127 (size: 36.3 KB, free: 389.6 MB)
15/03/19 21:16:50 INFO storage.BlockManagerInfo: Added rdd_3_7 in memory on
datanode01:59567 (size: 35.6 KB, free: 389.2 MB)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Starting task 8.0 in stage 3.0
(TID 56, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Finished task 6.0 in stage 3.0
(TID 54) in 54 ms on datanode03 (7/16)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Starting task 9.0 in stage 3.0
(TID 57, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Finished task 7.0 in stage 3.0
(TID 55) in 49 ms on datanode01 (8/16)
15/03/19 21:16:50 INFO storage.BlockManagerInfo: Added rdd_3_8 in memory on
datanode03:59127 (size: 38.1 KB, free: 389.6 MB)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Starting task 10.0 in stage
3.0 (TID 58, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Finished task 8.0 in stage 3.0
(TID 56) in 52 ms on datanode03 (9/16)
15/03/19 21:16:50 INFO storage.BlockManagerInfo: Added rdd_3_9 in memory on
datanode01:59567 (size: 43.6 KB, free: 389.2 MB)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Starting task 11.0 in stage
3.0 (TID 59, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:50 INFO scheduler.TaskSetManager: Finished task 9.0 in stage 3.0
(TID 57) in 60 ms on datanode01 (10/16)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Added rdd_3_10 in memory on
datanode03:59127 (size: 30.8 KB, free: 389.6 MB)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 12.0 in stage
3.0 (TID 60, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 10.0 in stage
3.0 (TID 58) in 46 ms on datanode03 (11/16)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Added rdd_3_11 in memory on
datanode01:59567 (size: 37.5 KB, free: 389.1 MB)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 13.0 in stage
3.0 (TID 61, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 11.0 in stage
3.0 (TID 59) in 50 ms on datanode01 (12/16)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Added rdd_3_12 in memory on
datanode03:59127 (size: 38.4 KB, free: 389.5 MB)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Added rdd_3_13 in memory on
datanode01:59567 (size: 34.1 KB, free: 389.1 MB)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 14.0 in stage
3.0 (TID 62, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 12.0 in stage
3.0 (TID 60) in 51 ms on datanode03 (13/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 15.0 in stage
3.0 (TID 63, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 13.0 in stage
3.0 (TID 61) in 41 ms on datanode01 (14/16)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Added rdd_3_14 in memory on
datanode03:59127 (size: 31.3 KB, free: 389.5 MB)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Added rdd_3_15 in memory on
datanode01:59567 (size: 41.7 KB, free: 389.1 MB)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 14.0 in stage
3.0 (TID 62) in 43 ms on datanode03 (15/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 15.0 in stage
3.0 (TID 63) in 47 ms on datanode01 (16/16)
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Stage 3 (count at
TestSparkApp.java:161) finished in 0.494 s
15/03/19 21:16:51 INFO cluster.YarnClusterScheduler: Removed TaskSet 3.0, whose
tasks have all completed, from pool
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Job 2 finished: count at
TestSparkApp.java:161, took 82.526383 s
15/03/19 21:16:51 INFO spark.SparkContext: Starting job: takeOrdered at
TestSparkApp.java:164
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Got job 3 (takeOrdered at
TestSparkApp.java:164) with 16 output partitions (allowLocal=false)
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Final stage: Stage 5(takeOrdered
at TestSparkApp.java:164)
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Parents of final stage:
List(Stage 4)
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Missing parents: List()
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Submitting Stage 5
(MapPartitionsRDD[4] at takeOrdered at TestSparkApp.java:164), which has no
missing parents
15/03/19 21:16:51 INFO storage.MemoryStore: ensureFreeSpace(7648) called with
curMem=174301, maxMem=270375321
15/03/19 21:16:51 INFO storage.MemoryStore: Block broadcast_5 stored as values
in memory (estimated size 7.5 KB, free 257.7 MB)
15/03/19 21:16:51 INFO storage.MemoryStore: ensureFreeSpace(5124) called with
curMem=181949, maxMem=270375321
15/03/19 21:16:51 INFO storage.MemoryStore: Block broadcast_5_piece0 stored as
bytes in memory (estimated size 5.0 KB, free 257.7 MB)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Added broadcast_5_piece0 in
memory on datanode03:59571 (size: 5.0 KB, free: 257.8 MB)
15/03/19 21:16:51 INFO storage.BlockManagerMaster: Updated info of block
broadcast_5_piece0
15/03/19 21:16:51 INFO spark.SparkContext: Created broadcast 5 from broadcast
at DAGScheduler.scala:838
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Submitting 16 missing tasks from
Stage 5 (MapPartitionsRDD[4] at takeOrdered at TestSparkApp.java:164)
15/03/19 21:16:51 INFO cluster.YarnClusterScheduler: Adding task set 5.0 with
16 tasks
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 5.0
(TID 64, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 1.0 in stage 5.0
(TID 65, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Added broadcast_5_piece0 in
memory on datanode03:59127 (size: 5.0 KB, free: 389.5 MB)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Added broadcast_5_piece0 in
memory on datanode01:59567 (size: 5.0 KB, free: 389.1 MB)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 3.0 in stage 5.0
(TID 66, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 2.0 in stage 5.0
(TID 67, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 1.0 in stage 5.0
(TID 65) in 46 ms on datanode03 (1/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 5.0
(TID 64) in 52 ms on datanode01 (2/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 5.0 in stage 5.0
(TID 68, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 3.0 in stage 5.0
(TID 66) in 9 ms on datanode03 (3/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 4.0 in stage 5.0
(TID 69, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 2.0 in stage 5.0
(TID 67) in 11 ms on datanode01 (4/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 6.0 in stage 5.0
(TID 70, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 5.0 in stage 5.0
(TID 68) in 10 ms on datanode03 (5/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 7.0 in stage 5.0
(TID 71, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 4.0 in stage 5.0
(TID 69) in 10 ms on datanode01 (6/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 8.0 in stage 5.0
(TID 72, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 6.0 in stage 5.0
(TID 70) in 9 ms on datanode03 (7/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 9.0 in stage 5.0
(TID 73, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 7.0 in stage 5.0
(TID 71) in 10 ms on datanode01 (8/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 10.0 in stage
5.0 (TID 74, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 8.0 in stage 5.0
(TID 72) in 9 ms on datanode03 (9/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 11.0 in stage
5.0 (TID 75, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 9.0 in stage 5.0
(TID 73) in 11 ms on datanode01 (10/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 12.0 in stage
5.0 (TID 76, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 10.0 in stage
5.0 (TID 74) in 9 ms on datanode03 (11/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 13.0 in stage
5.0 (TID 77, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 11.0 in stage
5.0 (TID 75) in 9 ms on datanode01 (12/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 14.0 in stage
5.0 (TID 78, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 12.0 in stage
5.0 (TID 76) in 9 ms on datanode03 (13/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 15.0 in stage
5.0 (TID 79, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 13.0 in stage
5.0 (TID 77) in 10 ms on datanode01 (14/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 14.0 in stage
5.0 (TID 78) in 9 ms on datanode03 (15/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 15.0 in stage
5.0 (TID 79) in 10 ms on datanode01 (16/16)
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Stage 5 (takeOrdered at
TestSparkApp.java:164) finished in 0.115 s
15/03/19 21:16:51 INFO cluster.YarnClusterScheduler: Removed TaskSet 5.0, whose
tasks have all completed, from pool
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Job 3 finished: takeOrdered at
TestSparkApp.java:164, took 0.137363 s
15/03/19 21:16:51 INFO spark.SparkContext: Starting job: takeOrdered at
TestSparkApp.java:168
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Got job 4 (takeOrdered at
TestSparkApp.java:168) with 16 output partitions (allowLocal=false)
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Final stage: Stage 7(takeOrdered
at TestSparkApp.java:168)
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Parents of final stage:
List(Stage 6)
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Missing parents: List()
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Submitting Stage 7
(MapPartitionsRDD[5] at takeOrdered at TestSparkApp.java:168), which has no
missing parents
15/03/19 21:16:51 INFO storage.MemoryStore: ensureFreeSpace(7656) called with
curMem=187073, maxMem=270375321
15/03/19 21:16:51 INFO storage.MemoryStore: Block broadcast_6 stored as values
in memory (estimated size 7.5 KB, free 257.7 MB)
15/03/19 21:16:51 INFO storage.MemoryStore: ensureFreeSpace(5127) called with
curMem=194729, maxMem=270375321
15/03/19 21:16:51 INFO storage.MemoryStore: Block broadcast_6_piece0 stored as
bytes in memory (estimated size 5.0 KB, free 257.7 MB)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Added broadcast_6_piece0 in
memory on datanode03:59571 (size: 5.0 KB, free: 257.8 MB)
15/03/19 21:16:51 INFO storage.BlockManagerMaster: Updated info of block
broadcast_6_piece0
15/03/19 21:16:51 INFO spark.SparkContext: Created broadcast 6 from broadcast
at DAGScheduler.scala:838
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Submitting 16 missing tasks from
Stage 7 (MapPartitionsRDD[5] at takeOrdered at TestSparkApp.java:168)
15/03/19 21:16:51 INFO cluster.YarnClusterScheduler: Adding task set 7.0 with
16 tasks
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 1.0 in stage 7.0
(TID 80, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 7.0
(TID 81, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Added broadcast_6_piece0 in
memory on datanode03:59127 (size: 5.0 KB, free: 389.5 MB)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Added broadcast_6_piece0 in
memory on datanode01:59567 (size: 5.0 KB, free: 389.1 MB)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 3.0 in stage 7.0
(TID 82, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 1.0 in stage 7.0
(TID 80) in 24 ms on datanode03 (1/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 2.0 in stage 7.0
(TID 83, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 7.0
(TID 81) in 26 ms on datanode01 (2/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 5.0 in stage 7.0
(TID 84, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 3.0 in stage 7.0
(TID 82) in 9 ms on datanode03 (3/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 4.0 in stage 7.0
(TID 85, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 2.0 in stage 7.0
(TID 83) in 10 ms on datanode01 (4/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 6.0 in stage 7.0
(TID 86, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 5.0 in stage 7.0
(TID 84) in 8 ms on datanode03 (5/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 7.0 in stage 7.0
(TID 87, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 4.0 in stage 7.0
(TID 85) in 10 ms on datanode01 (6/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 8.0 in stage 7.0
(TID 88, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 6.0 in stage 7.0
(TID 86) in 8 ms on datanode03 (7/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 9.0 in stage 7.0
(TID 89, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 7.0 in stage 7.0
(TID 87) in 10 ms on datanode01 (8/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 10.0 in stage
7.0 (TID 90, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 8.0 in stage 7.0
(TID 88) in 9 ms on datanode03 (9/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 12.0 in stage
7.0 (TID 91, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 10.0 in stage
7.0 (TID 90) in 7 ms on datanode03 (10/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 11.0 in stage
7.0 (TID 92, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 9.0 in stage 7.0
(TID 89) in 11 ms on datanode01 (11/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 14.0 in stage
7.0 (TID 93, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 12.0 in stage
7.0 (TID 91) in 8 ms on datanode03 (12/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 11.0 in stage
7.0 (TID 92) in 9 ms on datanode01 (13/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 13.0 in stage
7.0 (TID 94, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 14.0 in stage
7.0 (TID 93) in 7 ms on datanode03 (14/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 15.0 in stage
7.0 (TID 95, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 13.0 in stage
7.0 (TID 94) in 9 ms on datanode01 (15/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 15.0 in stage
7.0 (TID 95) in 9 ms on datanode01 (16/16)
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Stage 7 (takeOrdered at
TestSparkApp.java:168) finished in 0.091 s
15/03/19 21:16:51 INFO cluster.YarnClusterScheduler: Removed TaskSet 7.0, whose
tasks have all completed, from pool
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Job 4 finished: takeOrdered at
TestSparkApp.java:168, took 0.108964 s
15/03/19 21:16:51 INFO spark.SparkContext: Starting job: takeOrdered at
TestSparkApp.java:171
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Got job 5 (takeOrdered at
TestSparkApp.java:171) with 16 output partitions (allowLocal=false)
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Final stage: Stage 9(takeOrdered
at TestSparkApp.java:171)
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Parents of final stage:
List(Stage 8)
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Missing parents: List()
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Submitting Stage 9
(MapPartitionsRDD[6] at takeOrdered at TestSparkApp.java:171), which has no
missing parents
15/03/19 21:16:51 INFO storage.MemoryStore: ensureFreeSpace(7648) called with
curMem=199856, maxMem=270375321
15/03/19 21:16:51 INFO storage.MemoryStore: Block broadcast_7 stored as values
in memory (estimated size 7.5 KB, free 257.7 MB)
15/03/19 21:16:51 INFO storage.MemoryStore: ensureFreeSpace(5126) called with
curMem=207504, maxMem=270375321
15/03/19 21:16:51 INFO storage.MemoryStore: Block broadcast_7_piece0 stored as
bytes in memory (estimated size 5.0 KB, free 257.6 MB)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Added broadcast_7_piece0 in
memory on datanode03:59571 (size: 5.0 KB, free: 257.8 MB)
15/03/19 21:16:51 INFO storage.BlockManagerMaster: Updated info of block
broadcast_7_piece0
15/03/19 21:16:51 INFO spark.SparkContext: Created broadcast 7 from broadcast
at DAGScheduler.scala:838
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Submitting 16 missing tasks from
Stage 9 (MapPartitionsRDD[6] at takeOrdered at TestSparkApp.java:171)
15/03/19 21:16:51 INFO cluster.YarnClusterScheduler: Adding task set 9.0 with
16 tasks
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 9.0
(TID 96, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 1.0 in stage 9.0
(TID 97, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Added broadcast_7_piece0 in
memory on datanode03:59127 (size: 5.0 KB, free: 389.5 MB)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Added broadcast_7_piece0 in
memory on datanode01:59567 (size: 5.0 KB, free: 389.1 MB)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 3.0 in stage 9.0
(TID 98, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 1.0 in stage 9.0
(TID 97) in 22 ms on datanode03 (1/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 2.0 in stage 9.0
(TID 99, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 0.0 in stage 9.0
(TID 96) in 25 ms on datanode01 (2/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 5.0 in stage 9.0
(TID 100, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 3.0 in stage 9.0
(TID 98) in 7 ms on datanode03 (3/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 4.0 in stage 9.0
(TID 101, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 2.0 in stage 9.0
(TID 99) in 41 ms on datanode01 (4/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 6.0 in stage 9.0
(TID 102, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 5.0 in stage 9.0
(TID 100) in 39 ms on datanode03 (5/16)
15/03/19 21:16:51 INFO storage.BlockManager: Removing broadcast 6
15/03/19 21:16:51 INFO storage.BlockManager: Removing block broadcast_6_piece0
15/03/19 21:16:51 INFO storage.MemoryStore: Block broadcast_6_piece0 of size
5127 dropped from memory (free 270167818)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Removed broadcast_6_piece0 on
datanode03:59571 in memory (size: 5.0 KB, free: 257.8 MB)
15/03/19 21:16:51 INFO storage.BlockManagerMaster: Updated info of block
broadcast_6_piece0
15/03/19 21:16:51 INFO storage.BlockManager: Removing block broadcast_6
15/03/19 21:16:51 INFO storage.MemoryStore: Block broadcast_6 of size 7656
dropped from memory (free 270175474)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 7.0 in stage 9.0
(TID 103, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 4.0 in stage 9.0
(TID 101) in 14 ms on datanode01 (6/16)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Removed broadcast_6_piece0 on
datanode03:59127 in memory (size: 5.0 KB, free: 389.5 MB)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Removed broadcast_6_piece0 on
datanode01:59567 in memory (size: 5.0 KB, free: 389.1 MB)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 9.0 in stage 9.0
(TID 104, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 7.0 in stage 9.0
(TID 103) in 10 ms on datanode01 (7/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 8.0 in stage 9.0
(TID 105, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO spark.ContextCleaner: Cleaned broadcast 6
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 6.0 in stage 9.0
(TID 102) in 21 ms on datanode03 (8/16)
15/03/19 21:16:51 INFO storage.BlockManager: Removing broadcast 5
15/03/19 21:16:51 INFO storage.BlockManager: Removing block broadcast_5_piece0
15/03/19 21:16:51 INFO storage.MemoryStore: Block broadcast_5_piece0 of size
5124 dropped from memory (free 270180598)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Removed broadcast_5_piece0 on
datanode03:59571 in memory (size: 5.0 KB, free: 257.8 MB)
15/03/19 21:16:51 INFO storage.BlockManagerMaster: Updated info of block
broadcast_5_piece0
15/03/19 21:16:51 INFO storage.BlockManager: Removing block broadcast_5
15/03/19 21:16:51 INFO storage.MemoryStore: Block broadcast_5 of size 7648
dropped from memory (free 270188246)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Removed broadcast_5_piece0 on
datanode03:59127 in memory (size: 5.0 KB, free: 389.5 MB)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 11.0 in stage
9.0 (TID 106, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Removed broadcast_5_piece0 on
datanode01:59567 in memory (size: 5.0 KB, free: 389.1 MB)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 9.0 in stage 9.0
(TID 104) in 10 ms on datanode01 (9/16)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 10.0 in stage
9.0 (TID 107, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 8.0 in stage 9.0
(TID 105) in 9 ms on datanode03 (10/16)
15/03/19 21:16:51 INFO spark.ContextCleaner: Cleaned broadcast 5
15/03/19 21:16:51 INFO storage.BlockManager: Removing broadcast 4
15/03/19 21:16:51 INFO storage.BlockManager: Removing block broadcast_4
15/03/19 21:16:51 INFO storage.MemoryStore: Block broadcast_4 of size 6992
dropped from memory (free 270195238)
15/03/19 21:16:51 INFO storage.BlockManager: Removing block broadcast_4_piece0
15/03/19 21:16:51 INFO storage.MemoryStore: Block broadcast_4_piece0 of size
4628 dropped from memory (free 270199866)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Removed broadcast_4_piece0 on
datanode03:59571 in memory (size: 4.5 KB, free: 257.8 MB)
15/03/19 21:16:51 INFO storage.BlockManagerMaster: Updated info of block
broadcast_4_piece0
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 13.0 in stage
9.0 (TID 108, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Removed broadcast_4_piece0 on
datanode01:59567 in memory (size: 4.5 KB, free: 389.1 MB)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 11.0 in stage
9.0 (TID 106) in 12 ms on datanode01 (11/16)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Removed broadcast_4_piece0 on
datanode03:59127 in memory (size: 4.5 KB, free: 389.5 MB)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 12.0 in stage
9.0 (TID 109, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 10.0 in stage
9.0 (TID 107) in 12 ms on datanode03 (12/16)
15/03/19 21:16:51 INFO spark.ContextCleaner: Cleaned broadcast 4
15/03/19 21:16:51 INFO storage.BlockManager: Removing broadcast 3
15/03/19 21:16:51 INFO storage.BlockManager: Removing block broadcast_3_piece0
15/03/19 21:16:51 INFO storage.MemoryStore: Block broadcast_3_piece0 of size
4407 dropped from memory (free 270204273)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Removed broadcast_3_piece0 on
datanode03:59571 in memory (size: 4.3 KB, free: 257.8 MB)
15/03/19 21:16:51 INFO storage.BlockManagerMaster: Updated info of block
broadcast_3_piece0
15/03/19 21:16:51 INFO storage.BlockManager: Removing block broadcast_3
15/03/19 21:16:51 INFO storage.MemoryStore: Block broadcast_3 of size 6624
dropped from memory (free 270210897)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 15.0 in stage
9.0 (TID 110, datanode01, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 13.0 in stage
9.0 (TID 108) in 10 ms on datanode01 (13/16)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Removed broadcast_3_piece0 on
datanode01:59567 in memory (size: 4.3 KB, free: 389.1 MB)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Starting task 14.0 in stage
9.0 (TID 111, datanode03, PROCESS_LOCAL, 1056 bytes)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Removed broadcast_3_piece0 on
datanode03:59127 in memory (size: 4.3 KB, free: 389.5 MB)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 12.0 in stage
9.0 (TID 109) in 10 ms on datanode03 (14/16)
15/03/19 21:16:51 INFO spark.ContextCleaner: Cleaned broadcast 3
15/03/19 21:16:51 INFO storage.BlockManager: Removing broadcast 2
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 15.0 in stage
9.0 (TID 110) in 10 ms on datanode01 (15/16)
15/03/19 21:16:51 INFO storage.BlockManager: Removing block broadcast_2
15/03/19 21:16:51 INFO storage.MemoryStore: Block broadcast_2 of size 4672
dropped from memory (free 270215569)
15/03/19 21:16:51 INFO storage.BlockManager: Removing block broadcast_2_piece0
15/03/19 21:16:51 INFO storage.MemoryStore: Block broadcast_2_piece0 of size
3033 dropped from memory (free 270218602)
15/03/19 21:16:51 INFO scheduler.TaskSetManager: Finished task 14.0 in stage
9.0 (TID 111) in 8 ms on datanode03 (16/16)
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Stage 9 (takeOrdered at
TestSparkApp.java:171) finished in 0.125 s
15/03/19 21:16:51 INFO cluster.YarnClusterScheduler: Removed TaskSet 9.0, whose
tasks have all completed, from pool
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Removed broadcast_2_piece0 on
datanode03:59571 in memory (size: 3.0 KB, free: 257.8 MB)
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Job 5 finished: takeOrdered at
TestSparkApp.java:171, took 0.141627 s
15/03/19 21:16:51 INFO storage.BlockManagerMaster: Updated info of block
broadcast_2_piece0
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Removed broadcast_2_piece0 on
datanode03:59127 in memory (size: 3.0 KB, free: 389.5 MB)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Removed broadcast_2_piece0 on
datanode01:59567 in memory (size: 3.0 KB, free: 389.1 MB)
15/03/19 21:16:51 INFO yarn.ApplicationMaster: Final app status: SUCCEEDED,
exitCode: 0
15/03/19 21:16:51 INFO yarn.ApplicationMaster: Invoking sc stop from shutdown
hook
15/03/19 21:16:51 INFO spark.ContextCleaner: Cleaned broadcast 2
15/03/19 21:16:51 INFO storage.BlockManager: Removing broadcast 1
15/03/19 21:16:51 INFO storage.BlockManager: Removing block broadcast_1_piece0
15/03/19 21:16:51 INFO storage.MemoryStore: Block broadcast_1_piece0 of size
1896 dropped from memory (free 270220498)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Removed broadcast_1_piece0 on
datanode03:59571 in memory (size: 1896.0 B, free: 257.8 MB)
15/03/19 21:16:51 INFO storage.BlockManagerMaster: Updated info of block
broadcast_1_piece0
15/03/19 21:16:51 INFO storage.BlockManager: Removing block broadcast_1
15/03/19 21:16:51 INFO storage.MemoryStore: Block broadcast_1 of size 2544
dropped from memory (free 270223042)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Removed broadcast_1_piece0 on
datanode03:59127 in memory (size: 1896.0 B, free: 389.5 MB)
15/03/19 21:16:51 INFO storage.BlockManagerInfo: Removed broadcast_1_piece0 on
datanode01:59567 in memory (size: 1896.0 B, free: 389.1 MB)
15/03/19 21:16:51 INFO spark.ContextCleaner: Cleaned broadcast 1
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/stages/stage/kill,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/static,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/executors/threadDump/json,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/executors/threadDump,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/executors/json,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/executors,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/environment/json,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/environment,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/storage/rdd/json,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/storage/rdd,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/storage/json,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/storage,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/stages/pool/json,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/stages/pool,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/stages/stage/json,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/stages/stage,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/stages/json,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/stages,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/jobs/job/json,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/jobs/job,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/jobs/json,null}
15/03/19 21:16:51 INFO handler.ContextHandler: stopped
o.e.j.s.ServletContextHandler{/jobs,null}
15/03/19 21:16:51 INFO ui.SparkUI: Stopped Spark web UI at
http://datanode03:59140
15/03/19 21:16:51 INFO scheduler.DAGScheduler: Stopping DAGScheduler
15/03/19 21:16:51 INFO cluster.YarnClusterSchedulerBackend: Shutting down all
executors
15/03/19 21:16:51 INFO cluster.YarnClusterSchedulerBackend: Asking each
executor to shut down
15/03/19 21:16:52 INFO spark.MapOutputTrackerMasterActor: MapOutputTrackerActor
stopped!
15/03/19 21:16:52 INFO storage.MemoryStore: MemoryStore cleared
15/03/19 21:16:52 INFO storage.BlockManager: BlockManager stopped
15/03/19 21:16:52 INFO storage.BlockManagerMaster: BlockManagerMaster stopped
15/03/19 21:16:52 INFO spark.SparkContext: Successfully stopped SparkContext
15/03/19 21:16:52 INFO yarn.ApplicationMaster: Unregistering ApplicationMaster
with SUCCEEDED
15/03/19 21:16:52 INFO remote.RemoteActorRefProvider$RemotingTerminator:
Shutting down remote daemon.
15/03/19 21:16:52 INFO remote.RemoteActorRefProvider$RemotingTerminator: Remote
daemon shut down; proceeding with flushing remote transports.
15/03/19 21:16:52 INFO impl.AMRMClientImpl: Waiting for application to be
successfully unregistered.
15/03/19 21:16:52 INFO remote.RemoteActorRefProvider$RemotingTerminator:
Remoting shut down.
15/03/19 21:16:52 INFO yarn.ApplicationMaster: Deleting staging directory
.sparkStaging/application_1426685857620_0005
---------------------------------------------------------------------
To unsubscribe, e-mail: user-unsubscr...@spark.apache.org
For additional commands, e-mail: user-h...@spark.apache.org
