Spark小课堂Week6 启动日志详解

Spark小课堂Week6 启动日志详解

作为分布式系统，Spark程序是非常难以使用传统方法来进行调试的，所以我们主要的武器是日志，今天会对启动日志进行一下详解。

日志详解

今天主要遍历下Streaming的启动日志。

• 授权等操作

Using Spark's default log4j profile: org/apache/spark/log4j-defaults.properties
16/07/19 15:06:04 INFO SparkContext: Running Spark version 1.4.1
16/07/19 15:06:10 WARN NativeCodeLoader: Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
16/07/19 15:06:10 INFO SecurityManager: Changing view acls to: 
16/07/19 15:06:10 INFO SecurityManager: Changing modify acls to: 
16/07/19 15:06:10 INFO SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(); users with modify permissions: Set()
16/07/19 15:06:11 INFO Slf4jLogger: Slf4jLogger started

• 有中心式架构，元数据服务叫Driver，这里是启动了一个akka服务，会提供rpc调用。

16/07/19 15:06:11 INFO Remoting: Starting remoting
16/07/19 15:06:11 INFO Remoting: Remoting started; listening on addresses :[akka.tcp://sparkDriver@84.232.207.171:46561]
16/07/19 15:06:11 INFO Utils: Successfully started service 'sparkDriver' on port 46561.

• SparkEnv类似一个地址簿，会管理所有Spark自身的服务
• 启动数据管理服务，这里是初始分配存储，包括分配磁盘和内存两部分

16/07/19 15:06:11 INFO SparkEnv: Registering MapOutputTracker
16/07/19 15:06:11 INFO SparkEnv: Registering BlockManagerMaster
16/07/19 15:06:11 INFO DiskBlockManager: Created local directory at C:\Users\kfzx-zhongw\AppData\Local\Temp\spark-45392ea0-70f1-4562-b251-22521756a1d3\blockmgr-b6eb9263-5a04-4cc9-83b9-fcbe153808b8
16/07/19 15:06:11 INFO MemoryStore: MemoryStore started with capacity 133.6 MB

• 这里的file server主要是管理jar包等基础文件的

16/07/19 15:06:11 INFO HttpFileServer: HTTP File server directory is C:\Users\kfzx-zhongw\AppData\Local\Temp\spark-45392ea0-70f1-4562-b251-22521756a1d3\httpd-69699a3d-70f7-4a99-8ae8-9527ca666cdb
16/07/19 15:06:11 INFO HttpServer: Starting HTTP Server
16/07/19 15:06:11 INFO Utils: Successfully started service 'HTTP file server' on port 46562.
16/07/19 15:06:11 INFO SparkEnv: Registering OutputCommitCoordinator

• 启动UI服务，底层是一个Jetty

16/07/19 15:06:11 INFO Utils: Successfully started service 'SparkUI' on port 4040.
16/07/19 15:06:11 INFO SparkUI: Started SparkUI at http://84.232.207.171:4040

• 这里启动数据传输服务，是一个netty服务

16/07/19 15:06:11 INFO Executor: Starting executor ID driver on host localhost
16/07/19 15:06:12 INFO Utils: Successfully started service 'org.apache.spark.network.netty.NettyBlockTransferService' on port 46581.
16/07/19 15:06:12 INFO NettyBlockTransferService: Server created on 46581
16/07/19 15:06:12 INFO BlockManagerMaster: Trying to register BlockManager
16/07/19 15:06:12 INFO BlockManagerMasterEndpoint: Registering block manager localhost:46581 with 133.6 MB RAM, BlockManagerId(driver, localhost, 46581)
16/07/19 15:06:12 INFO BlockManagerMaster: Registered BlockManager

• 至此，Spark的核心部分启动完成，下面是SparkStreaming的启动。

• 业务逻辑对象初始化，这里是从后往前调用，从前往后运行。

16/07/19 15:06:12 INFO ReceiverTracker: ReceiverTracker started

16/07/19 15:06:12 INFO ForEachDStream: metadataCleanupDelay = -1
16/07/19 15:06:12 INFO ShuffledDStream: metadataCleanupDelay = -1
16/07/19 15:06:12 INFO MappedDStream: metadataCleanupDelay = -1
16/07/19 15:06:12 INFO FlatMappedDStream: metadataCleanupDelay = -1
16/07/19 15:06:12 INFO SocketInputDStream: metadataCleanupDelay = -1

16/07/19 15:06:12 INFO SocketInputDStream: Slide time = 10000 ms
16/07/19 15:06:12 INFO SocketInputDStream: Storage level = StorageLevel(false, false, false, false, 1)
16/07/19 15:06:12 INFO SocketInputDStream: Checkpoint interval = null
16/07/19 15:06:12 INFO SocketInputDStream: Remember duration = 10000 ms
16/07/19 15:06:12 INFO ReceiverTracker: Starting 1 receivers
16/07/19 15:06:12 INFO SocketInputDStream: Initialized and validated org.apache.spark.streaming.dstream.SocketInputDStream@819867
16/07/19 15:06:12 INFO FlatMappedDStream: Slide time = 10000 ms
16/07/19 15:06:12 INFO FlatMappedDStream: Storage level = StorageLevel(false, false, false, false, 1)
16/07/19 15:06:12 INFO FlatMappedDStream: Checkpoint interval = null
16/07/19 15:06:12 INFO FlatMappedDStream: Remember duration = 10000 ms
16/07/19 15:06:12 INFO FlatMappedDStream: Initialized and validated org.apache.spark.streaming.dstream.FlatMappedDStream@18102ee
16/07/19 15:06:12 INFO MappedDStream: Slide time = 10000 ms
16/07/19 15:06:12 INFO MappedDStream: Storage level = StorageLevel(false, false, false, false, 1)
16/07/19 15:06:12 INFO MappedDStream: Checkpoint interval = null
16/07/19 15:06:12 INFO MappedDStream: Remember duration = 10000 ms
16/07/19 15:06:12 INFO MappedDStream: Initialized and validated org.apache.spark.streaming.dstream.MappedDStream@cd9a2c
16/07/19 15:06:12 INFO ShuffledDStream: Slide time = 10000 ms
16/07/19 15:06:12 INFO ShuffledDStream: Storage level = StorageLevel(false, false, false, false, 1)
16/07/19 15:06:12 INFO ShuffledDStream: Checkpoint interval = null
16/07/19 15:06:12 INFO ShuffledDStream: Remember duration = 10000 ms
16/07/19 15:06:12 INFO ShuffledDStream: Initialized and validated org.apache.spark.streaming.dstream.ShuffledDStream@11d1ffb
16/07/19 15:06:12 INFO ForEachDStream: Slide time = 10000 ms
16/07/19 15:06:12 INFO ForEachDStream: Storage level = StorageLevel(false, false, false, false, 1)
16/07/19 15:06:12 INFO ForEachDStream: Checkpoint interval = null
16/07/19 15:06:12 INFO ForEachDStream: Remember duration = 10000 ms
16/07/19 15:06:12 INFO ForEachDStream: Initialized and validated org.apache.spark.streaming.dstream.ForEachDStream@167e3df

• Streaming中最重要的组件，四个组件是从外置内套着的。

16/07/19 15:06:12 INFO RecurringTimer: Started timer for JobGenerator at time 1468911980000
16/07/19 15:06:12 INFO JobGenerator: Started JobGenerator at 1468911980000 ms
16/07/19 15:06:12 INFO JobScheduler: Started JobScheduler
16/07/19 15:06:12 INFO StreamingContext: StreamingContext started

• 启动Job0，这个是Streaming的socket数据接收服务

16/07/19 15:06:12 INFO SparkContext: Starting job: start at JavaOnlineWordCount.java:32
16/07/19 15:06:12 INFO DAGScheduler: Got job 0 (start at JavaOnlineWordCount.java:32) with 1 output partitions (allowLocal=false)
16/07/19 15:06:12 INFO DAGScheduler: Final stage: ResultStage 0(start at JavaOnlineWordCount.java:32)
16/07/19 15:06:12 INFO DAGScheduler: Parents of final stage: List()
16/07/19 15:06:12 INFO DAGScheduler: Missing parents: List()
16/07/19 15:06:12 INFO DAGScheduler: Submitting ResultStage 0 (ParallelCollectionRDD[0] at start at JavaOnlineWordCount.java:32), which has no missing parents
16/07/19 15:06:13 WARN SizeEstimator: Failed to check whether UseCompressedOops is set; assuming yes
16/07/19 15:06:13 INFO MemoryStore: ensureFreeSpace(46352) called with curMem=0, maxMem=140142182
16/07/19 15:06:13 INFO MemoryStore: Block broadcast_0 stored as values in memory (estimated size 45.3 KB, free 133.6 MB)
16/07/19 15:06:13 INFO MemoryStore: ensureFreeSpace(15070) called with curMem=46352, maxMem=140142182
16/07/19 15:06:13 INFO MemoryStore: Block broadcast_0_piece0 stored as bytes in memory (estimated size 14.7 KB, free 133.6 MB)
16/07/19 15:06:13 INFO BlockManagerInfo: Added broadcast_0_piece0 in memory on localhost:46581 (size: 14.7 KB, free: 133.6 MB)
16/07/19 15:06:13 INFO SparkContext: Created broadcast 0 from broadcast at DAGScheduler.scala:874
16/07/19 15:06:13 INFO DAGScheduler: Submitting 1 missing tasks from ResultStage 0 (ParallelCollectionRDD[0] at start at JavaOnlineWordCount.java:32)
16/07/19 15:06:13 INFO TaskSchedulerImpl: Adding task set 0.0 with 1 tasks
16/07/19 15:06:13 INFO TaskSetManager: Starting task 0.0 in stage 0.0 (TID 0, localhost, PROCESS_LOCAL, 2000 bytes)
16/07/19 15:06:13 INFO Executor: Running task 0.0 in stage 0.0 (TID 0)
16/07/19 15:06:13 INFO RecurringTimer: Started timer for BlockGenerator at time 1468911973400
16/07/19 15:06:13 INFO BlockGenerator: Started block pushing thread
16/07/19 15:06:13 INFO BlockGenerator: Started BlockGenerator
16/07/19 15:06:13 INFO ReceiverSupervisorImpl: Starting receiver
16/07/19 15:06:13 INFO ReceiverSupervisorImpl: Called receiver onStart
16/07/19 15:06:13 INFO SocketReceiver: Connecting to localhost:9999
16/07/19 15:06:13 INFO SocketReceiver: Connected to localhost:9999
16/07/19 15:06:13 INFO ReceiverTracker: Registered receiver for stream 0 from 84.232.207.171:46561

• 获取外部输入数据，这里会调用memoryStore

16/07/19 15:06:19 INFO MemoryStore: ensureFreeSpace(15) called with curMem=61422, maxMem=140142182
16/07/19 15:06:19 INFO MemoryStore: Block input-0-1468911978800 stored as bytes in memory (estimated size 15.0 B, free 133.6 MB)
16/07/19 15:06:19 INFO BlockManagerInfo: Added input-0-1468911978800 in memory on localhost:46581 (size: 15.0 B, free: 133.6 MB)
16/07/19 15:06:19 WARN BlockManager: Block input-0-1468911978800 replicated to only 0 peer(s) instead of 1 peers
16/07/19 15:06:19 INFO BlockGenerator: Pushed block input-0-1468911978800

• 执行业务逻辑计算，这里是核心！！！

16/07/19 15:06:20 INFO JobScheduler: Added jobs for time 1468911980000 ms
16/07/19 15:06:20 INFO JobScheduler: Starting job streaming job 1468911980000 ms.0 from job set of time 1468911980000 ms
16/07/19 15:06:20 INFO SparkContext: Starting job: print at JavaOnlineWordCount.java:30
16/07/19 15:06:20 INFO DAGScheduler: Registering RDD 3 (mapToPair at JavaOnlineWordCount.java:28)
16/07/19 15:06:20 INFO DAGScheduler: Got job 1 (print at JavaOnlineWordCount.java:30) with 1 output partitions (allowLocal=true)
16/07/19 15:06:20 INFO DAGScheduler: Final stage: ResultStage 2(print at JavaOnlineWordCount.java:30)
16/07/19 15:06:20 INFO DAGScheduler: Parents of final stage: List(ShuffleMapStage 1)
16/07/19 15:06:20 INFO DAGScheduler: Missing parents: List(ShuffleMapStage 1)
16/07/19 15:06:20 INFO DAGScheduler: Submitting ShuffleMapStage 1 (MapPartitionsRDD[3] at mapToPair at JavaOnlineWordCount.java:28), which has no missing parents
16/07/19 15:06:20 INFO MemoryStore: ensureFreeSpace(4016) called with curMem=61437, maxMem=140142182
16/07/19 15:06:20 INFO MemoryStore: Block broadcast_1 stored as values in memory (estimated size 3.9 KB, free 133.6 MB)
16/07/19 15:06:20 INFO MemoryStore: ensureFreeSpace(2297) called with curMem=65453, maxMem=140142182
16/07/19 15:06:20 INFO MemoryStore: Block broadcast_1_piece0 stored as bytes in memory (estimated size 2.2 KB, free 133.6 MB)
16/07/19 15:06:20 INFO BlockManagerInfo: Added broadcast_1_piece0 in memory on localhost:46581 (size: 2.2 KB, free: 133.6 MB)
16/07/19 15:06:20 INFO SparkContext: Created broadcast 1 from broadcast at DAGScheduler.scala:874
16/07/19 15:06:20 INFO DAGScheduler: Submitting 1 missing tasks from ShuffleMapStage 1 (MapPartitionsRDD[3] at mapToPair at JavaOnlineWordCount.java:28)
16/07/19 15:06:20 INFO TaskSchedulerImpl: Adding task set 1.0 with 1 tasks
16/07/19 15:06:20 INFO TaskSetManager: Starting task 0.0 in stage 1.0 (TID 1, localhost, NODE_LOCAL, 1277 bytes)
16/07/19 15:06:20 INFO Executor: Running task 0.0 in stage 1.0 (TID 1)
16/07/19 15:06:20 INFO BlockManager: Found block input-0-1468911978800 locally
16/07/19 15:06:20 INFO Executor: Finished task 0.0 in stage 1.0 (TID 1). 894 bytes result sent to driver
16/07/19 15:06:20 INFO TaskSetManager: Finished task 0.0 in stage 1.0 (TID 1) in 80 ms on localhost (1/1)
16/07/19 15:06:20 INFO TaskSchedulerImpl: Removed TaskSet 1.0, whose tasks have all completed, from pool 
16/07/19 15:06:20 INFO DAGScheduler: ShuffleMapStage 1 (mapToPair at JavaOnlineWordCount.java:28) finished in 0.084 s
16/07/19 15:06:20 INFO DAGScheduler: looking for newly runnable stages
16/07/19 15:06:20 INFO DAGScheduler: running: Set(ResultStage 0)
16/07/19 15:06:20 INFO DAGScheduler: waiting: Set(ResultStage 2)
16/07/19 15:06:20 INFO DAGScheduler: failed: Set()
16/07/19 15:06:20 INFO DAGScheduler: Missing parents for ResultStage 2: List()
16/07/19 15:06:20 INFO DAGScheduler: Submitting ResultStage 2 (ShuffledRDD[4] at reduceByKey at JavaOnlineWordCount.java:29), which is now runnable
16/07/19 15:06:20 INFO MemoryStore: ensureFreeSpace(3056) called with curMem=67750, maxMem=140142182
16/07/19 15:06:20 INFO MemoryStore: Block broadcast_2 stored as values in memory (estimated size 3.0 KB, free 133.6 MB)
16/07/19 15:06:20 INFO MemoryStore: ensureFreeSpace(1825) called with curMem=70806, maxMem=140142182
16/07/19 15:06:20 INFO MemoryStore: Block broadcast_2_piece0 stored as bytes in memory (estimated size 1825.0 B, free 133.6 MB)
16/07/19 15:06:20 INFO BlockManagerInfo: Added broadcast_2_piece0 in memory on localhost:46581 (size: 1825.0 B, free: 133.6 MB)
16/07/19 15:06:20 INFO SparkContext: Created broadcast 2 from broadcast at DAGScheduler.scala:874
16/07/19 15:06:20 INFO DAGScheduler: Submitting 1 missing tasks from ResultStage 2 (ShuffledRDD[4] at reduceByKey at JavaOnlineWordCount.java:29)
16/07/19 15:06:20 INFO TaskSchedulerImpl: Adding task set 2.0 with 1 tasks
16/07/19 15:06:20 INFO TaskSetManager: Starting task 0.0 in stage 2.0 (TID 2, localhost, PROCESS_LOCAL, 1165 bytes)
16/07/19 15:06:20 INFO Executor: Running task 0.0 in stage 2.0 (TID 2)
16/07/19 15:06:20 INFO ShuffleBlockFetcherIterator: Getting 0 non-empty blocks out of 1 blocks
16/07/19 15:06:20 INFO ShuffleBlockFetcherIterator: Started 0 remote fetches in 5 ms
16/07/19 15:06:20 INFO Executor: Finished task 0.0 in stage 2.0 (TID 2). 882 bytes result sent to driver
16/07/19 15:06:20 INFO TaskSetManager: Finished task 0.0 in stage 2.0 (TID 2) in 33 ms on localhost (1/1)
16/07/19 15:06:20 INFO DAGScheduler: ResultStage 2 (print at JavaOnlineWordCount.java:30) finished in 0.033 s
16/07/19 15:06:20 INFO TaskSchedulerImpl: Removed TaskSet 2.0, whose tasks have all completed, from pool 
16/07/19 15:06:20 INFO DAGScheduler: Job 1 finished: print at JavaOnlineWordCount.java:30, took 0.184378 s
...

• 结果输出：

-------------------------------------------
Time: 1468911980000 ms
-------------------------------------------
(123,1)
(1231,1)

• 执行清理操作

16/07/19 15:06:20 INFO JobScheduler: Finished job streaming job 1468911980000 ms.0 from job set of time 1468911980000 ms
16/07/19 15:06:20 INFO JobScheduler: Total delay: 0.440 s for time 1468911980000 ms (execution: 0.359 s)
16/07/19 15:06:20 INFO ReceivedBlockTracker: Deleting batches ArrayBuffer()
16/07/19 15:06:20 INFO InputInfoTracker: remove old batch metadata: 

关于

小课堂是在公司进行内部交流的一系列主题，偏基础，但是比较零散，持续更新中。