CaffeOnSpark Test failure when building Caffe on Spark

Test failure when building Caffe on Spark

Open xiaoyongzhu opened this issue 8 years ago • 5 comments
I am trying to build Caffe and it succeeds. However when running the automated tests during the building phase, there is one test failure (others are successful). The failure is similar with issue #184. Since other tests passed, I guess this might be some issue with this specific test case?

- Binary2Sequence
2017-01-11 19:51:40,085 [ScalaTest-main-running-ToolTest] INFO  handler.ContextHandler - Started o.s.j.s.ServletContextHandler@5e360c3b{/SQL,null,AVAILABLE}
2017-01-11 19:51:40,085 [ScalaTest-main-running-ToolTest] INFO  handler.ContextHandler - Started o.s.j.s.ServletContextHandler@3cb49121{/SQL/json,null,AVAILABLE}
2017-01-11 19:51:40,086 [ScalaTest-main-running-ToolTest] INFO  handler.ContextHandler - Started o.s.j.s.ServletContextHandler@6de5ad56{/SQL/execution,null,AVAILABLE}
2017-01-11 19:51:40,086 [ScalaTest-main-running-ToolTest] INFO  handler.ContextHandler - Started o.s.j.s.ServletContextHandler@cfb94fd{/SQL/execution/json,null,AVAILABLE}
2017-01-11 19:51:40,087 [ScalaTest-main-running-ToolTest] INFO  handler.ContextHandler - Started o.s.j.s.ServletContextHandler@a6fc1bc{/static/sql,null,AVAILABLE}
2017-01-11 19:51:40,087 [ScalaTest-main-running-ToolTest] INFO  internal.SharedState - Warehouse path is 'file:/home/xiaoyzhu/Test2/CaffeOnSpark/caffe-grid/spark-warehouse'.
2017-01-11 19:51:40,151 [ScalaTest-main-running-ToolTest] INFO  memory.MemoryStore - Block broadcast_4 stored as values in memory (estimated size 261.6 KB, free 3.5 GB)
2017-01-11 19:51:40,163 [ScalaTest-main-running-ToolTest] INFO  memory.MemoryStore - Block broadcast_4_piece0 stored as bytes in memory (estimated size 22.5 KB, free 3.5 GB)
2017-01-11 19:51:40,163 [dispatcher-event-loop-6] INFO  storage.BlockManagerInfo - Added broadcast_4_piece0 in memory on localhost:39435 (size: 22.5 KB, free: 3.5 GB)
2017-01-11 19:51:40,164 [ScalaTest-main-running-ToolTest] INFO  spark.SparkContext - Created broadcast 4 from json at Conversions.scala:33
2017-01-11 19:51:40,177 [ScalaTest-main-running-ToolTest] INFO  mapred.FileInputFormat - Total input paths to process : 1
2017-01-11 19:51:40,179 [ScalaTest-main-running-ToolTest] INFO  spark.SparkContext - Starting job: json at Conversions.scala:33
2017-01-11 19:51:40,180 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Got job 2 (json at Conversions.scala:33) with 1 output partitions
2017-01-11 19:51:40,180 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Final stage: ResultStage 2 (json at Conversions.scala:33)
2017-01-11 19:51:40,180 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Parents of final stage: List()
2017-01-11 19:51:40,180 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Missing parents: List()
2017-01-11 19:51:40,180 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ResultStage 2 (MapPartitionsRDD[7] at json at Conversions.scala:33), which has no missing parents
2017-01-11 19:51:40,181 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_5 stored as values in memory (estimated size 4.2 KB, free 3.5 GB)
2017-01-11 19:51:40,197 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_5_piece0 stored as bytes in memory (estimated size 2.5 KB, free 3.5 GB)
2017-01-11 19:51:40,198 [dispatcher-event-loop-7] INFO  storage.BlockManagerInfo - Added broadcast_5_piece0 in memory on localhost:39435 (size: 2.5 KB, free: 3.5 GB)
2017-01-11 19:51:40,199 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 5 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:40,199 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 1 missing tasks from ResultStage 2 (MapPartitionsRDD[7] at json at Conversions.scala:33)
2017-01-11 19:51:40,199 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 2.0 with 1 tasks
2017-01-11 19:51:40,200 [dispatcher-event-loop-1] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 2.0 (TID 2, localhost, partition 0, PROCESS_LOCAL, 5415 bytes)
2017-01-11 19:51:40,200 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 2.0 (TID 2)
2017-01-11 19:51:40,200 [dispatcher-event-loop-7] INFO  storage.BlockManagerInfo - Removed broadcast_0_piece0 on localhost:39435 in memory (size: 22.1 KB, free: 3.5 GB)
2017-01-11 19:51:40,203 [Executor task launch worker-0] INFO  rdd.HadoopRDD - Input split: file:/home/xiaoyzhu/Test2/CaffeOnSpark/caffe-grid/src/test/resources/coco.json:0+998
2017-01-11 19:51:40,203 [dispatcher-event-loop-0] INFO  storage.BlockManagerInfo - Removed broadcast_1_piece0 on localhost:39435 in memory (size: 2.5 KB, free: 3.5 GB)
2017-01-11 19:51:40,204 [dispatcher-event-loop-3] INFO  storage.BlockManagerInfo - Removed broadcast_2_piece0 on localhost:39435 in memory (size: 22.1 KB, free: 3.5 GB)
2017-01-11 19:51:40,205 [dispatcher-event-loop-6] INFO  storage.BlockManagerInfo - Removed broadcast_3_piece0 on localhost:39435 in memory (size: 1843.0 B, free: 3.5 GB)
2017-01-11 19:51:40,211 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 2.0 (TID 2). 2332 bytes result sent to driver
2017-01-11 19:51:40,216 [task-result-getter-2] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 2.0 (TID 2) in 17 ms on localhost (1/1)
2017-01-11 19:51:40,216 [task-result-getter-2] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 2.0, whose tasks have all completed, from pool
2017-01-11 19:51:40,216 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ResultStage 2 (json at Conversions.scala:33) finished in 0.017 s
2017-01-11 19:51:40,216 [ScalaTest-main-running-ToolTest] INFO  scheduler.DAGScheduler - Job 2 finished: json at Conversions.scala:33, took 0.037163 s
2017-01-11 19:51:40,294 [ScalaTest-main-running-ToolTest] INFO  datasources.FileSourceStrategy - Pruning directories with:
2017-01-11 19:51:40,295 [ScalaTest-main-running-ToolTest] INFO  datasources.FileSourceStrategy - Post-Scan Filters:
2017-01-11 19:51:40,299 [ScalaTest-main-running-ToolTest] INFO  datasources.FileSourceStrategy - Pruned Data Schema: struct<annotations: array<struct<caption:string,id:bigint,image_id:bigint>>>
2017-01-11 19:51:40,299 [ScalaTest-main-running-ToolTest] INFO  datasources.FileSourceStrategy - Pushed Filters:
2017-01-11 19:51:40,301 [ScalaTest-main-running-ToolTest] INFO  memory.MemoryStore - Block broadcast_6 stored as values in memory (estimated size 261.1 KB, free 3.5 GB)
2017-01-11 19:51:40,312 [ScalaTest-main-running-ToolTest] INFO  memory.MemoryStore - Block broadcast_6_piece0 stored as bytes in memory (estimated size 22.4 KB, free 3.5 GB)
2017-01-11 19:51:40,312 [dispatcher-event-loop-0] INFO  storage.BlockManagerInfo - Added broadcast_6_piece0 in memory on localhost:39435 (size: 22.4 KB, free: 3.5 GB)
2017-01-11 19:51:40,313 [ScalaTest-main-running-ToolTest] INFO  spark.SparkContext - Created broadcast 6 from rdd at Conversions.scala:39
2017-01-11 19:51:40,316 [ScalaTest-main-running-ToolTest] INFO  datasources.FileSourceStrategy - Planning scan with bin packing, max size: 4195302 bytes, open cost is considered as scanning 4194304 bytes.
2017-01-11 19:51:40,371 [ScalaTest-main-running-ToolTest] INFO  codegen.CodeGenerator - Code generated in 16.984701 ms
2017-01-11 19:51:40,405 [ScalaTest-main-running-ToolTest] INFO  datasources.FileSourceStrategy - Pruning directories with:
2017-01-11 19:51:40,405 [ScalaTest-main-running-ToolTest] INFO  datasources.FileSourceStrategy - Post-Scan Filters:
2017-01-11 19:51:40,406 [ScalaTest-main-running-ToolTest] INFO  datasources.FileSourceStrategy - Pruned Data Schema: struct<images: array<struct<coco_url:string,date_captured:string,file_name:string,flickr_url:string,height:bigint,id:bigint,license:bigint,width:bigint>>>
2017-01-11 19:51:40,406 [ScalaTest-main-running-ToolTest] INFO  datasources.FileSourceStrategy - Pushed Filters:
2017-01-11 19:51:40,407 [ScalaTest-main-running-ToolTest] INFO  memory.MemoryStore - Block broadcast_7 stored as values in memory (estimated size 261.1 KB, free 3.5 GB)
2017-01-11 19:51:40,415 [ScalaTest-main-running-ToolTest] INFO  memory.MemoryStore - Block broadcast_7_piece0 stored as bytes in memory (estimated size 22.4 KB, free 3.5 GB)
2017-01-11 19:51:40,415 [dispatcher-event-loop-1] INFO  storage.BlockManagerInfo - Added broadcast_7_piece0 in memory on localhost:39435 (size: 22.4 KB, free: 3.5 GB)
2017-01-11 19:51:40,416 [ScalaTest-main-running-ToolTest] INFO  spark.SparkContext - Created broadcast 7 from rdd at Conversions.scala:55
2017-01-11 19:51:40,416 [ScalaTest-main-running-ToolTest] INFO  datasources.FileSourceStrategy - Planning scan with bin packing, max size: 4195302 bytes, open cost is considered as scanning 4194304 bytes.
2017-01-11 19:51:40,445 [ScalaTest-main-running-ToolTest] INFO  codegen.CodeGenerator - Code generated in 19.840202 ms
2017-01-11 19:51:40,522 [ScalaTest-main-running-ToolTest] INFO  spark.SparkContext - Starting job: count at ToolTest.scala:99
2017-01-11 19:51:40,523 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Registering RDD 21 (coalesce at Conversions.scala:55)
2017-01-11 19:51:40,523 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Registering RDD 12 (coalesce at Conversions.scala:40)
2017-01-11 19:51:40,523 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Registering RDD 16 (flatMap at Conversions.scala:40)
2017-01-11 19:51:40,523 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Registering RDD 25 (flatMap at Conversions.scala:55)
2017-01-11 19:51:40,524 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Registering RDD 33 (count at ToolTest.scala:99)
2017-01-11 19:51:40,524 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Got job 3 (count at ToolTest.scala:99) with 1 output partitions
2017-01-11 19:51:40,524 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Final stage: ResultStage 8 (count at ToolTest.scala:99)
2017-01-11 19:51:40,524 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Parents of final stage: List(ShuffleMapStage 7)
2017-01-11 19:51:40,524 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Missing parents: List(ShuffleMapStage 7)
2017-01-11 19:51:40,524 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ShuffleMapStage 4 (MapPartitionsRDD[12] at coalesce at Conversions.scala:40), which has no missing parents
2017-01-11 19:51:40,540 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_8 stored as values in memory (estimated size 19.6 KB, free 3.5 GB)
2017-01-11 19:51:40,541 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_8_piece0 stored as bytes in memory (estimated size 8.7 KB, free 3.5 GB)
2017-01-11 19:51:40,541 [dispatcher-event-loop-2] INFO  storage.BlockManagerInfo - Added broadcast_8_piece0 in memory on localhost:39435 (size: 8.7 KB, free: 3.5 GB)
2017-01-11 19:51:40,541 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 8 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:40,542 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 4 (MapPartitionsRDD[12] at coalesce at Conversions.scala:40)
2017-01-11 19:51:40,542 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 4.0 with 1 tasks
2017-01-11 19:51:40,542 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ShuffleMapStage 3 (MapPartitionsRDD[21] at coalesce at Conversions.scala:55), which has no missing parents
2017-01-11 19:51:40,545 [dispatcher-event-loop-3] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 4.0 (TID 3, localhost, partition 0, PROCESS_LOCAL, 5895 bytes)
2017-01-11 19:51:40,546 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 4.0 (TID 3)
2017-01-11 19:51:40,571 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_9 stored as values in memory (estimated size 24.7 KB, free 3.5 GB)
2017-01-11 19:51:40,572 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_9_piece0 stored as bytes in memory (estimated size 9.6 KB, free 3.5 GB)
2017-01-11 19:51:40,572 [dispatcher-event-loop-7] INFO  storage.BlockManagerInfo - Added broadcast_9_piece0 in memory on localhost:39435 (size: 9.6 KB, free: 3.5 GB)
2017-01-11 19:51:40,573 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 9 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:40,573 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 3 (MapPartitionsRDD[21] at coalesce at Conversions.scala:55)
2017-01-11 19:51:40,573 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 3.0 with 1 tasks
2017-01-11 19:51:40,588 [Executor task launch worker-0] INFO  codegen.CodeGenerator - Code generated in 30.80449 ms
2017-01-11 19:51:40,590 [Executor task launch worker-0] INFO  datasources.FileScanRDD - Reading File path: file:///home/xiaoyzhu/Test2/CaffeOnSpark/caffe-grid/src/test/resources/coco.json, range: 0-998, partition values: [empty row]
2017-01-11 19:51:40,601 [Executor task launch worker-0] INFO  codegen.CodeGenerator - Code generated in 8.922616 ms
2017-01-11 19:51:40,615 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 4.0 (TID 3). 1548 bytes result sent to driver
2017-01-11 19:51:40,616 [dispatcher-event-loop-5] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 3.0 (TID 4, localhost, partition 0, PROCESS_LOCAL, 5895 bytes)
2017-01-11 19:51:40,616 [task-result-getter-3] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 4.0 (TID 3) in 74 ms on localhost (1/1)
2017-01-11 19:51:40,616 [task-result-getter-3] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 4.0, whose tasks have all completed, from pool
2017-01-11 19:51:40,617 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ShuffleMapStage 4 (coalesce at Conversions.scala:40) finished in 0.074 s
2017-01-11 19:51:40,617 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - looking for newly runnable stages
2017-01-11 19:51:40,617 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - running: Set(ShuffleMapStage 3)
2017-01-11 19:51:40,617 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - waiting: Set(ShuffleMapStage 5, ShuffleMapStage 6, ShuffleMapStage 7, ResultStage 8)
2017-01-11 19:51:40,617 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - failed: Set()
2017-01-11 19:51:40,617 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ShuffleMapStage 5 (MapPartitionsRDD[16] at flatMap at Conversions.scala:40), which has no missing parents
2017-01-11 19:51:40,619 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_10 stored as values in memory (estimated size 3.4 KB, free 3.5 GB)
2017-01-11 19:51:40,620 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_10_piece0 stored as bytes in memory (estimated size 2.0 KB, free 3.5 GB)
2017-01-11 19:51:40,620 [dispatcher-event-loop-0] INFO  storage.BlockManagerInfo - Added broadcast_10_piece0 in memory on localhost:39435 (size: 2.0 KB, free: 3.5 GB)
2017-01-11 19:51:40,621 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 10 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:40,621 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 4 missing tasks from ShuffleMapStage 5 (MapPartitionsRDD[16] at flatMap at Conversions.scala:40)
2017-01-11 19:51:40,621 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 5.0 with 4 tasks
2017-01-11 19:51:40,622 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 3.0 (TID 4)
2017-01-11 19:51:40,651 [Executor task launch worker-0] INFO  codegen.CodeGenerator - Code generated in 23.157419 ms
2017-01-11 19:51:40,652 [Executor task launch worker-0] INFO  datasources.FileScanRDD - Reading File path: file:///home/xiaoyzhu/Test2/CaffeOnSpark/caffe-grid/src/test/resources/coco.json, range: 0-998, partition values: [empty row]
2017-01-11 19:51:40,661 [Executor task launch worker-0] INFO  codegen.CodeGenerator - Code generated in 8.883214 ms
2017-01-11 19:51:40,666 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 3.0 (TID 4). 1548 bytes result sent to driver
2017-01-11 19:51:40,669 [dispatcher-event-loop-3] INFO  scheduler.TaskSetManager - Starting task 3.0 in stage 5.0 (TID 5, localhost, partition 3, NODE_LOCAL, 5402 bytes)
2017-01-11 19:51:40,669 [task-result-getter-0] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 3.0 (TID 4) in 53 ms on localhost (1/1)
2017-01-11 19:51:40,669 [task-result-getter-0] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 3.0, whose tasks have all completed, from pool
2017-01-11 19:51:40,669 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ShuffleMapStage 3 (coalesce at Conversions.scala:55) finished in 0.096 s
2017-01-11 19:51:40,669 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - looking for newly runnable stages
2017-01-11 19:51:40,669 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - running: Set(ShuffleMapStage 5)
2017-01-11 19:51:40,669 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - waiting: Set(ShuffleMapStage 6, ShuffleMapStage 7, ResultStage 8)
2017-01-11 19:51:40,669 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - failed: Set()
2017-01-11 19:51:40,670 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ShuffleMapStage 6 (MapPartitionsRDD[25] at flatMap at Conversions.scala:55), which has no missing parents
2017-01-11 19:51:40,671 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_11 stored as values in memory (estimated size 3.4 KB, free 3.5 GB)
2017-01-11 19:51:40,671 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_11_piece0 stored as bytes in memory (estimated size 2.0 KB, free 3.5 GB)
2017-01-11 19:51:40,672 [Executor task launch worker-0] INFO  executor.Executor - Running task 3.0 in stage 5.0 (TID 5)
2017-01-11 19:51:40,672 [dispatcher-event-loop-4] INFO  storage.BlockManagerInfo - Added broadcast_11_piece0 in memory on localhost:39435 (size: 2.0 KB, free: 3.5 GB)
2017-01-11 19:51:40,672 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 11 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:40,672 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 4 missing tasks from ShuffleMapStage 6 (MapPartitionsRDD[25] at flatMap at Conversions.scala:55)
2017-01-11 19:51:40,672 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 6.0 with 4 tasks
2017-01-11 19:51:40,675 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 1 blocks
2017-01-11 19:51:40,675 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 1 ms
2017-01-11 19:51:40,677 [Executor task launch worker-0] INFO  executor.Executor - Finished task 3.0 in stage 5.0 (TID 5). 1634 bytes result sent to driver
2017-01-11 19:51:40,677 [dispatcher-event-loop-5] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 5.0 (TID 6, localhost, partition 0, PROCESS_LOCAL, 5402 bytes)
2017-01-11 19:51:40,678 [task-result-getter-1] INFO  scheduler.TaskSetManager - Finished task 3.0 in stage 5.0 (TID 5) in 11 ms on localhost (1/4)
2017-01-11 19:51:40,678 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 5.0 (TID 6)
2017-01-11 19:51:40,679 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 1 blocks
2017-01-11 19:51:40,679 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,680 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 5.0 (TID 6). 1286 bytes result sent to driver
2017-01-11 19:51:40,680 [dispatcher-event-loop-1] INFO  scheduler.TaskSetManager - Starting task 1.0 in stage 5.0 (TID 7, localhost, partition 1, PROCESS_LOCAL, 5402 bytes)
2017-01-11 19:51:40,680 [Executor task launch worker-0] INFO  executor.Executor - Running task 1.0 in stage 5.0 (TID 7)
2017-01-11 19:51:40,680 [task-result-getter-2] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 5.0 (TID 6) in 3 ms on localhost (2/4)
2017-01-11 19:51:40,682 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 1 blocks
2017-01-11 19:51:40,682 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,682 [Executor task launch worker-0] INFO  executor.Executor - Finished task 1.0 in stage 5.0 (TID 7). 1365 bytes result sent to driver
2017-01-11 19:51:40,683 [dispatcher-event-loop-3] INFO  scheduler.TaskSetManager - Starting task 2.0 in stage 5.0 (TID 8, localhost, partition 2, PROCESS_LOCAL, 5402 bytes)
2017-01-11 19:51:40,683 [task-result-getter-3] INFO  scheduler.TaskSetManager - Finished task 1.0 in stage 5.0 (TID 7) in 3 ms on localhost (3/4)
2017-01-11 19:51:40,683 [Executor task launch worker-0] INFO  executor.Executor - Running task 2.0 in stage 5.0 (TID 8)
2017-01-11 19:51:40,684 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 1 blocks
2017-01-11 19:51:40,684 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,685 [Executor task launch worker-0] INFO  executor.Executor - Finished task 2.0 in stage 5.0 (TID 8). 1278 bytes result sent to driver
2017-01-11 19:51:40,685 [dispatcher-event-loop-4] INFO  scheduler.TaskSetManager - Starting task 3.0 in stage 6.0 (TID 9, localhost, partition 3, NODE_LOCAL, 5402 bytes)
2017-01-11 19:51:40,685 [task-result-getter-0] INFO  scheduler.TaskSetManager - Finished task 2.0 in stage 5.0 (TID 8) in 3 ms on localhost (4/4)
2017-01-11 19:51:40,685 [task-result-getter-0] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 5.0, whose tasks have all completed, from pool
2017-01-11 19:51:40,685 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ShuffleMapStage 5 (flatMap at Conversions.scala:40) finished in 0.064 s
2017-01-11 19:51:40,686 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - looking for newly runnable stages
2017-01-11 19:51:40,686 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - running: Set(ShuffleMapStage 6)
2017-01-11 19:51:40,686 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - waiting: Set(ShuffleMapStage 7, ResultStage 8)
2017-01-11 19:51:40,686 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - failed: Set()
2017-01-11 19:51:40,686 [Executor task launch worker-0] INFO  executor.Executor - Running task 3.0 in stage 6.0 (TID 9)
2017-01-11 19:51:40,687 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 1 blocks
2017-01-11 19:51:40,687 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,689 [Executor task launch worker-0] INFO  executor.Executor - Finished task 3.0 in stage 6.0 (TID 9). 1634 bytes result sent to driver
2017-01-11 19:51:40,690 [dispatcher-event-loop-5] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 6.0 (TID 10, localhost, partition 0, PROCESS_LOCAL, 5402 bytes)
2017-01-11 19:51:40,690 [task-result-getter-1] INFO  scheduler.TaskSetManager - Finished task 3.0 in stage 6.0 (TID 9) in 5 ms on localhost (1/4)
2017-01-11 19:51:40,690 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 6.0 (TID 10)
2017-01-11 19:51:40,691 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 1 blocks
2017-01-11 19:51:40,692 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 1 ms
2017-01-11 19:51:40,692 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 6.0 (TID 10). 1365 bytes result sent to driver
2017-01-11 19:51:40,692 [dispatcher-event-loop-1] INFO  scheduler.TaskSetManager - Starting task 1.0 in stage 6.0 (TID 11, localhost, partition 1, PROCESS_LOCAL, 5402 bytes)
2017-01-11 19:51:40,693 [task-result-getter-2] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 6.0 (TID 10) in 3 ms on localhost (2/4)
2017-01-11 19:51:40,694 [Executor task launch worker-0] INFO  executor.Executor - Running task 1.0 in stage 6.0 (TID 11)
2017-01-11 19:51:40,695 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 1 blocks
2017-01-11 19:51:40,695 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,696 [Executor task launch worker-0] INFO  executor.Executor - Finished task 1.0 in stage 6.0 (TID 11). 1278 bytes result sent to driver
2017-01-11 19:51:40,696 [dispatcher-event-loop-3] INFO  scheduler.TaskSetManager - Starting task 2.0 in stage 6.0 (TID 12, localhost, partition 2, PROCESS_LOCAL, 5402 bytes)
2017-01-11 19:51:40,696 [task-result-getter-3] INFO  scheduler.TaskSetManager - Finished task 1.0 in stage 6.0 (TID 11) in 4 ms on localhost (3/4)
2017-01-11 19:51:40,697 [Executor task launch worker-0] INFO  executor.Executor - Running task 2.0 in stage 6.0 (TID 12)
2017-01-11 19:51:40,698 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 1 blocks
2017-01-11 19:51:40,698 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,698 [Executor task launch worker-0] INFO  executor.Executor - Finished task 2.0 in stage 6.0 (TID 12). 1278 bytes result sent to driver
2017-01-11 19:51:40,698 [task-result-getter-0] INFO  scheduler.TaskSetManager - Finished task 2.0 in stage 6.0 (TID 12) in 2 ms on localhost (4/4)
2017-01-11 19:51:40,699 [task-result-getter-0] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 6.0, whose tasks have all completed, from pool
2017-01-11 19:51:40,699 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ShuffleMapStage 6 (flatMap at Conversions.scala:55) finished in 0.027 s
2017-01-11 19:51:40,699 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - looking for newly runnable stages
2017-01-11 19:51:40,699 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - running: Set()
2017-01-11 19:51:40,699 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - waiting: Set(ShuffleMapStage 7, ResultStage 8)
2017-01-11 19:51:40,699 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - failed: Set()
2017-01-11 19:51:40,699 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ShuffleMapStage 7 (MapPartitionsRDD[33] at count at ToolTest.scala:99), which has no missing parents
2017-01-11 19:51:40,707 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_12 stored as values in memory (estimated size 13.9 KB, free 3.5 GB)
2017-01-11 19:51:40,708 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_12_piece0 stored as bytes in memory (estimated size 6.9 KB, free 3.5 GB)
2017-01-11 19:51:40,708 [dispatcher-event-loop-6] INFO  storage.BlockManagerInfo - Added broadcast_12_piece0 in memory on localhost:39435 (size: 6.9 KB, free: 3.5 GB)
2017-01-11 19:51:40,709 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 12 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:40,709 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 4 missing tasks from ShuffleMapStage 7 (MapPartitionsRDD[33] at count at ToolTest.scala:99)
2017-01-11 19:51:40,709 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 7.0 with 4 tasks
2017-01-11 19:51:40,710 [dispatcher-event-loop-5] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 7.0 (TID 13, localhost, partition 0, PROCESS_LOCAL, 5223 bytes)
2017-01-11 19:51:40,710 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 7.0 (TID 13)
2017-01-11 19:51:40,714 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 4 blocks
2017-01-11 19:51:40,714 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,714 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 4 blocks
2017-01-11 19:51:40,715 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 1 ms
2017-01-11 19:51:40,729 [Executor task launch worker-0] INFO  codegen.CodeGenerator - Code generated in 6.655836 ms
2017-01-11 19:51:40,732 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 7.0 (TID 13). 2433 bytes result sent to driver
2017-01-11 19:51:40,732 [dispatcher-event-loop-1] INFO  scheduler.TaskSetManager - Starting task 1.0 in stage 7.0 (TID 14, localhost, partition 1, PROCESS_LOCAL, 5223 bytes)
2017-01-11 19:51:40,733 [Executor task launch worker-0] INFO  executor.Executor - Running task 1.0 in stage 7.0 (TID 14)
2017-01-11 19:51:40,733 [task-result-getter-1] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 7.0 (TID 13) in 24 ms on localhost (1/4)
2017-01-11 19:51:40,736 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 4 blocks
2017-01-11 19:51:40,736 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,736 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 4 blocks
2017-01-11 19:51:40,736 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,738 [Executor task launch worker-0] INFO  executor.Executor - Finished task 1.0 in stage 7.0 (TID 14). 2433 bytes result sent to driver
2017-01-11 19:51:40,739 [dispatcher-event-loop-3] INFO  scheduler.TaskSetManager - Starting task 2.0 in stage 7.0 (TID 15, localhost, partition 2, PROCESS_LOCAL, 5223 bytes)
2017-01-11 19:51:40,739 [Executor task launch worker-0] INFO  executor.Executor - Running task 2.0 in stage 7.0 (TID 15)
2017-01-11 19:51:40,739 [task-result-getter-2] INFO  scheduler.TaskSetManager - Finished task 1.0 in stage 7.0 (TID 14) in 7 ms on localhost (2/4)
2017-01-11 19:51:40,742 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 4 blocks
2017-01-11 19:51:40,742 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,742 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 4 blocks
2017-01-11 19:51:40,742 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,776 [Executor task launch worker-0] INFO  codegen.CodeGenerator - Code generated in 26.055622 ms
2017-01-11 19:51:40,779 [Executor task launch worker-0] INFO  executor.Executor - Finished task 2.0 in stage 7.0 (TID 15). 2433 bytes result sent to driver
2017-01-11 19:51:40,780 [dispatcher-event-loop-4] INFO  scheduler.TaskSetManager - Starting task 3.0 in stage 7.0 (TID 16, localhost, partition 3, PROCESS_LOCAL, 5223 bytes)
2017-01-11 19:51:40,780 [task-result-getter-3] INFO  scheduler.TaskSetManager - Finished task 2.0 in stage 7.0 (TID 15) in 41 ms on localhost (3/4)
2017-01-11 19:51:40,780 [Executor task launch worker-0] INFO  executor.Executor - Running task 3.0 in stage 7.0 (TID 16)
2017-01-11 19:51:40,783 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 4 blocks
2017-01-11 19:51:40,783 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,783 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 4 blocks
2017-01-11 19:51:40,783 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,788 [Executor task launch worker-0] INFO  executor.Executor - Finished task 3.0 in stage 7.0 (TID 16). 2433 bytes result sent to driver
2017-01-11 19:51:40,788 [task-result-getter-0] INFO  scheduler.TaskSetManager - Finished task 3.0 in stage 7.0 (TID 16) in 9 ms on localhost (4/4)
2017-01-11 19:51:40,788 [task-result-getter-0] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 7.0, whose tasks have all completed, from pool
2017-01-11 19:51:40,788 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ShuffleMapStage 7 (count at ToolTest.scala:99) finished in 0.079 s
2017-01-11 19:51:40,788 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - looking for newly runnable stages
2017-01-11 19:51:40,788 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - running: Set()
2017-01-11 19:51:40,788 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - waiting: Set(ResultStage 8)
2017-01-11 19:51:40,788 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - failed: Set()
2017-01-11 19:51:40,788 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ResultStage 8 (MapPartitionsRDD[36] at count at ToolTest.scala:99), which has no missing parents
2017-01-11 19:51:40,789 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_13 stored as values in memory (estimated size 7.0 KB, free 3.5 GB)
2017-01-11 19:51:40,790 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_13_piece0 stored as bytes in memory (estimated size 3.7 KB, free 3.5 GB)
2017-01-11 19:51:40,791 [dispatcher-event-loop-0] INFO  storage.BlockManagerInfo - Added broadcast_13_piece0 in memory on localhost:39435 (size: 3.7 KB, free: 3.5 GB)
2017-01-11 19:51:40,791 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 13 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:40,791 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 1 missing tasks from ResultStage 8 (MapPartitionsRDD[36] at count at ToolTest.scala:99)
2017-01-11 19:51:40,791 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 8.0 with 1 tasks
2017-01-11 19:51:40,792 [dispatcher-event-loop-1] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 8.0 (TID 17, localhost, partition 0, NODE_LOCAL, 5276 bytes)
2017-01-11 19:51:40,792 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 8.0 (TID 17)
2017-01-11 19:51:40,793 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 4 non-empty blocks out of 4 blocks
2017-01-11 19:51:40,793 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,794 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 8.0 (TID 17). 1873 bytes result sent to driver
2017-01-11 19:51:40,795 [task-result-getter-1] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 8.0 (TID 17) in 4 ms on localhost (1/1)
2017-01-11 19:51:40,795 [task-result-getter-1] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 8.0, whose tasks have all completed, from pool
2017-01-11 19:51:40,795 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ResultStage 8 (count at ToolTest.scala:99) finished in 0.004 s
2017-01-11 19:51:40,795 [ScalaTest-main-running-ToolTest] INFO  scheduler.DAGScheduler - Job 3 finished: count at ToolTest.scala:99, took 0.273497 s
2017-01-11 19:51:40,815 [ScalaTest-main-running-ToolTest] INFO  codegen.CodeGenerator - Code generated in 5.605399 ms
2017-01-11 19:51:40,838 [ScalaTest-main-running-ToolTest] INFO  spark.SparkContext - Starting job: sortBy at Vocab.scala:31
2017-01-11 19:51:40,924 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 1 is 146 bytes
2017-01-11 19:51:40,925 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 0 is 146 bytes
2017-01-11 19:51:40,925 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 4 is 157 bytes
2017-01-11 19:51:40,925 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 3 is 157 bytes
2017-01-11 19:51:40,926 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Registering RDD 42 (map at Vocab.scala:31)
2017-01-11 19:51:40,926 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Got job 4 (sortBy at Vocab.scala:31) with 4 output partitions
2017-01-11 19:51:40,926 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Final stage: ResultStage 14 (sortBy at Vocab.scala:31)
2017-01-11 19:51:40,926 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Parents of final stage: List(ShuffleMapStage 13)
2017-01-11 19:51:40,926 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Missing parents: List(ShuffleMapStage 13)
2017-01-11 19:51:40,926 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ShuffleMapStage 13 (MapPartitionsRDD[42] at map at Vocab.scala:31), which has no missing parents
2017-01-11 19:51:40,931 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_14 stored as values in memory (estimated size 14.6 KB, free 3.5 GB)
2017-01-11 19:51:40,932 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_14_piece0 stored as bytes in memory (estimated size 7.2 KB, free 3.5 GB)
2017-01-11 19:51:40,933 [dispatcher-event-loop-7] INFO  storage.BlockManagerInfo - Added broadcast_14_piece0 in memory on localhost:39435 (size: 7.2 KB, free: 3.5 GB)
2017-01-11 19:51:40,933 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 14 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:40,933 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 4 missing tasks from ShuffleMapStage 13 (MapPartitionsRDD[42] at map at Vocab.scala:31)
2017-01-11 19:51:40,933 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 13.0 with 4 tasks
2017-01-11 19:51:40,934 [dispatcher-event-loop-4] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 13.0 (TID 18, localhost, partition 0, PROCESS_LOCAL, 5193 bytes)
2017-01-11 19:51:40,934 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 13.0 (TID 18)
2017-01-11 19:51:40,936 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 4 blocks
2017-01-11 19:51:40,936 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,937 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 4 blocks
2017-01-11 19:51:40,937 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,945 [Executor task launch worker-0] INFO  codegen.CodeGenerator - Code generated in 5.320688 ms
2017-01-11 19:51:40,959 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 13.0 (TID 18). 2003 bytes result sent to driver
2017-01-11 19:51:40,959 [dispatcher-event-loop-5] INFO  scheduler.TaskSetManager - Starting task 1.0 in stage 13.0 (TID 19, localhost, partition 1, PROCESS_LOCAL, 5193 bytes)
2017-01-11 19:51:40,959 [Executor task launch worker-0] INFO  executor.Executor - Running task 1.0 in stage 13.0 (TID 19)
2017-01-11 19:51:40,960 [task-result-getter-2] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 13.0 (TID 18) in 27 ms on localhost (1/4)
2017-01-11 19:51:40,962 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 4 blocks
2017-01-11 19:51:40,962 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,962 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 4 blocks
2017-01-11 19:51:40,962 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,968 [Executor task launch worker-0] INFO  executor.Executor - Finished task 1.0 in stage 13.0 (TID 19). 2003 bytes result sent to driver
2017-01-11 19:51:40,968 [dispatcher-event-loop-1] INFO  scheduler.TaskSetManager - Starting task 2.0 in stage 13.0 (TID 20, localhost, partition 2, PROCESS_LOCAL, 5193 bytes)
2017-01-11 19:51:40,968 [Executor task launch worker-0] INFO  executor.Executor - Running task 2.0 in stage 13.0 (TID 20)
2017-01-11 19:51:40,968 [task-result-getter-3] INFO  scheduler.TaskSetManager - Finished task 1.0 in stage 13.0 (TID 19) in 9 ms on localhost (2/4)
2017-01-11 19:51:40,971 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 4 blocks
2017-01-11 19:51:40,971 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,972 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 4 blocks
2017-01-11 19:51:40,972 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 1 ms
2017-01-11 19:51:40,985 [Executor task launch worker-0] INFO  executor.Executor - Finished task 2.0 in stage 13.0 (TID 20). 2185 bytes result sent to driver
2017-01-11 19:51:40,985 [dispatcher-event-loop-3] INFO  scheduler.TaskSetManager - Starting task 3.0 in stage 13.0 (TID 21, localhost, partition 3, PROCESS_LOCAL, 5193 bytes)
2017-01-11 19:51:40,985 [Executor task launch worker-0] INFO  executor.Executor - Running task 3.0 in stage 13.0 (TID 21)
2017-01-11 19:51:40,985 [task-result-getter-0] INFO  scheduler.TaskSetManager - Finished task 2.0 in stage 13.0 (TID 20) in 17 ms on localhost (3/4)
2017-01-11 19:51:40,988 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 4 blocks
2017-01-11 19:51:40,988 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,988 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 4 blocks
2017-01-11 19:51:40,988 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:40,996 [Executor task launch worker-0] INFO  executor.Executor - Finished task 3.0 in stage 13.0 (TID 21). 2185 bytes result sent to driver
2017-01-11 19:51:40,997 [task-result-getter-1] INFO  scheduler.TaskSetManager - Finished task 3.0 in stage 13.0 (TID 21) in 12 ms on localhost (4/4)
2017-01-11 19:51:40,997 [task-result-getter-1] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 13.0, whose tasks have all completed, from pool
2017-01-11 19:51:40,997 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ShuffleMapStage 13 (map at Vocab.scala:31) finished in 0.064 s
2017-01-11 19:51:40,997 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - looking for newly runnable stages
2017-01-11 19:51:40,997 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - running: Set()
2017-01-11 19:51:40,997 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - waiting: Set(ResultStage 14)
2017-01-11 19:51:40,997 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - failed: Set()
2017-01-11 19:51:40,997 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ResultStage 14 (MapPartitionsRDD[46] at sortBy at Vocab.scala:31), which has no missing parents
2017-01-11 19:51:40,999 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_15 stored as values in memory (estimated size 4.2 KB, free 3.5 GB)
2017-01-11 19:51:40,999 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_15_piece0 stored as bytes in memory (estimated size 2.4 KB, free 3.5 GB)
2017-01-11 19:51:41,000 [dispatcher-event-loop-6] INFO  storage.BlockManagerInfo - Added broadcast_15_piece0 in memory on localhost:39435 (size: 2.4 KB, free: 3.5 GB)
2017-01-11 19:51:41,000 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 15 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:41,000 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 4 missing tasks from ResultStage 14 (MapPartitionsRDD[46] at sortBy at Vocab.scala:31)
2017-01-11 19:51:41,000 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 14.0 with 4 tasks
2017-01-11 19:51:41,001 [dispatcher-event-loop-5] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 14.0 (TID 22, localhost, partition 0, NODE_LOCAL, 5141 bytes)
2017-01-11 19:51:41,001 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 14.0 (TID 22)
2017-01-11 19:51:41,003 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,003 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 1 ms
2017-01-11 19:51:41,009 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 14.0 (TID 22). 1786 bytes result sent to driver
2017-01-11 19:51:41,009 [dispatcher-event-loop-1] INFO  scheduler.TaskSetManager - Starting task 1.0 in stage 14.0 (TID 23, localhost, partition 1, NODE_LOCAL, 5141 bytes)
2017-01-11 19:51:41,010 [Executor task launch worker-0] INFO  executor.Executor - Running task 1.0 in stage 14.0 (TID 23)
2017-01-11 19:51:41,010 [task-result-getter-2] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 14.0 (TID 22) in 8 ms on localhost (1/4)
2017-01-11 19:51:41,011 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 2 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,011 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 1 ms
2017-01-11 19:51:41,014 [Executor task launch worker-0] INFO  executor.Executor - Finished task 1.0 in stage 14.0 (TID 23). 1711 bytes result sent to driver
2017-01-11 19:51:41,014 [dispatcher-event-loop-3] INFO  scheduler.TaskSetManager - Starting task 2.0 in stage 14.0 (TID 24, localhost, partition 2, NODE_LOCAL, 5141 bytes)
2017-01-11 19:51:41,015 [Executor task launch worker-0] INFO  executor.Executor - Running task 2.0 in stage 14.0 (TID 24)
2017-01-11 19:51:41,015 [task-result-getter-3] INFO  scheduler.TaskSetManager - Finished task 1.0 in stage 14.0 (TID 23) in 6 ms on localhost (2/4)
2017-01-11 19:51:41,016 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 2 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,016 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,019 [Executor task launch worker-0] INFO  executor.Executor - Finished task 2.0 in stage 14.0 (TID 24). 1715 bytes result sent to driver
2017-01-11 19:51:41,019 [dispatcher-event-loop-4] INFO  scheduler.TaskSetManager - Starting task 3.0 in stage 14.0 (TID 25, localhost, partition 3, NODE_LOCAL, 5141 bytes)
2017-01-11 19:51:41,020 [Executor task launch worker-0] INFO  executor.Executor - Running task 3.0 in stage 14.0 (TID 25)
2017-01-11 19:51:41,020 [task-result-getter-0] INFO  scheduler.TaskSetManager - Finished task 2.0 in stage 14.0 (TID 24) in 5 ms on localhost (3/4)
2017-01-11 19:51:41,022 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 2 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,022 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 1 ms
2017-01-11 19:51:41,025 [Executor task launch worker-0] INFO  executor.Executor - Finished task 3.0 in stage 14.0 (TID 25). 1794 bytes result sent to driver
2017-01-11 19:51:41,025 [task-result-getter-1] INFO  scheduler.TaskSetManager - Finished task 3.0 in stage 14.0 (TID 25) in 6 ms on localhost (4/4)
2017-01-11 19:51:41,025 [task-result-getter-1] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 14.0, whose tasks have all completed, from pool
2017-01-11 19:51:41,026 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ResultStage 14 (sortBy at Vocab.scala:31) finished in 0.026 s
2017-01-11 19:51:41,026 [ScalaTest-main-running-ToolTest] INFO  scheduler.DAGScheduler - Job 4 finished: sortBy at Vocab.scala:31, took 0.187513 s
2017-01-11 19:51:41,033 [ScalaTest-main-running-ToolTest] INFO  spark.SparkContext - Starting job: count at Vocab.scala:32
2017-01-11 19:51:41,034 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 1 is 146 bytes
2017-01-11 19:51:41,035 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 0 is 146 bytes
2017-01-11 19:51:41,035 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 4 is 157 bytes
2017-01-11 19:51:41,035 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 3 is 157 bytes
2017-01-11 19:51:41,036 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 5 is 164 bytes
2017-01-11 19:51:41,036 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Registering RDD 44 (sortBy at Vocab.scala:31)
2017-01-11 19:51:41,036 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Got job 5 (count at Vocab.scala:32) with 2 output partitions
2017-01-11 19:51:41,036 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Final stage: ResultStage 21 (count at Vocab.scala:32)
2017-01-11 19:51:41,036 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Parents of final stage: List(ShuffleMapStage 20)
2017-01-11 19:51:41,036 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Missing parents: List(ShuffleMapStage 20)
2017-01-11 19:51:41,036 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ShuffleMapStage 20 (MapPartitionsRDD[44] at sortBy at Vocab.scala:31), which has no missing parents
2017-01-11 19:51:41,040 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_16 stored as values in memory (estimated size 4.1 KB, free 3.5 GB)
2017-01-11 19:51:41,041 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_16_piece0 stored as bytes in memory (estimated size 2.4 KB, free 3.5 GB)
2017-01-11 19:51:41,041 [dispatcher-event-loop-0] INFO  storage.BlockManagerInfo - Added broadcast_16_piece0 in memory on localhost:39435 (size: 2.4 KB, free: 3.5 GB)
2017-01-11 19:51:41,041 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 16 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:41,041 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 4 missing tasks from ShuffleMapStage 20 (MapPartitionsRDD[44] at sortBy at Vocab.scala:31)
2017-01-11 19:51:41,041 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 20.0 with 4 tasks
2017-01-11 19:51:41,042 [dispatcher-event-loop-1] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 20.0 (TID 26, localhost, partition 0, NODE_LOCAL, 5045 bytes)
2017-01-11 19:51:41,042 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 20.0 (TID 26)
2017-01-11 19:51:41,044 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,044 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,048 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 20.0 (TID 26). 1877 bytes result sent to driver
2017-01-11 19:51:41,048 [dispatcher-event-loop-3] INFO  scheduler.TaskSetManager - Starting task 1.0 in stage 20.0 (TID 27, localhost, partition 1, NODE_LOCAL, 5045 bytes)
2017-01-11 19:51:41,048 [Executor task launch worker-0] INFO  executor.Executor - Running task 1.0 in stage 20.0 (TID 27)
2017-01-11 19:51:41,048 [task-result-getter-2] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 20.0 (TID 26) in 6 ms on localhost (1/4)
2017-01-11 19:51:41,049 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 2 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,050 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 1 ms
2017-01-11 19:51:41,053 [Executor task launch worker-0] INFO  executor.Executor - Finished task 1.0 in stage 20.0 (TID 27). 1877 bytes result sent to driver
2017-01-11 19:51:41,053 [dispatcher-event-loop-4] INFO  scheduler.TaskSetManager - Starting task 2.0 in stage 20.0 (TID 28, localhost, partition 2, NODE_LOCAL, 5045 bytes)
2017-01-11 19:51:41,053 [Executor task launch worker-0] INFO  executor.Executor - Running task 2.0 in stage 20.0 (TID 28)
2017-01-11 19:51:41,054 [task-result-getter-3] INFO  scheduler.TaskSetManager - Finished task 1.0 in stage 20.0 (TID 27) in 6 ms on localhost (2/4)
2017-01-11 19:51:41,054 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 2 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,054 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,058 [Executor task launch worker-0] INFO  executor.Executor - Finished task 2.0 in stage 20.0 (TID 28). 1877 bytes result sent to driver
2017-01-11 19:51:41,058 [dispatcher-event-loop-5] INFO  scheduler.TaskSetManager - Starting task 3.0 in stage 20.0 (TID 29, localhost, partition 3, NODE_LOCAL, 5045 bytes)
2017-01-11 19:51:41,058 [Executor task launch worker-0] INFO  executor.Executor - Running task 3.0 in stage 20.0 (TID 29)
2017-01-11 19:51:41,058 [task-result-getter-0] INFO  scheduler.TaskSetManager - Finished task 2.0 in stage 20.0 (TID 28) in 5 ms on localhost (3/4)
2017-01-11 19:51:41,059 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 2 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,059 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,063 [Executor task launch worker-0] INFO  executor.Executor - Finished task 3.0 in stage 20.0 (TID 29). 1877 bytes result sent to driver
2017-01-11 19:51:41,063 [task-result-getter-1] INFO  scheduler.TaskSetManager - Finished task 3.0 in stage 20.0 (TID 29) in 5 ms on localhost (4/4)
2017-01-11 19:51:41,063 [task-result-getter-1] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 20.0, whose tasks have all completed, from pool
2017-01-11 19:51:41,063 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ShuffleMapStage 20 (sortBy at Vocab.scala:31) finished in 0.022 s
2017-01-11 19:51:41,063 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - looking for newly runnable stages
2017-01-11 19:51:41,063 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - running: Set()
2017-01-11 19:51:41,063 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - waiting: Set(ResultStage 21)
2017-01-11 19:51:41,063 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - failed: Set()
2017-01-11 19:51:41,064 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ResultStage 21 (MapPartitionsRDD[48] at sortBy at Vocab.scala:31), which has no missing parents
2017-01-11 19:51:41,064 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_17 stored as values in memory (estimated size 3.3 KB, free 3.5 GB)
2017-01-11 19:51:41,065 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_17_piece0 stored as bytes in memory (estimated size 1948.0 B, free 3.5 GB)
2017-01-11 19:51:41,066 [dispatcher-event-loop-2] INFO  storage.BlockManagerInfo - Added broadcast_17_piece0 in memory on localhost:39435 (size: 1948.0 B, free: 3.5 GB)
2017-01-11 19:51:41,066 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 17 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:41,066 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 2 missing tasks from ResultStage 21 (MapPartitionsRDD[48] at sortBy at Vocab.scala:31)
2017-01-11 19:51:41,066 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 21.0 with 2 tasks
2017-01-11 19:51:41,067 [dispatcher-event-loop-3] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 21.0 (TID 30, localhost, partition 0, NODE_LOCAL, 5056 bytes)
2017-01-11 19:51:41,067 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 21.0 (TID 30)
2017-01-11 19:51:41,068 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 4 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,068 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,074 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 21.0 (TID 30). 1591 bytes result sent to driver
2017-01-11 19:51:41,074 [dispatcher-event-loop-4] INFO  scheduler.TaskSetManager - Starting task 1.0 in stage 21.0 (TID 31, localhost, partition 1, PROCESS_LOCAL, 5056 bytes)
2017-01-11 19:51:41,074 [Executor task launch worker-0] INFO  executor.Executor - Running task 1.0 in stage 21.0 (TID 31)
2017-01-11 19:51:41,074 [task-result-getter-2] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 21.0 (TID 30) in 8 ms on localhost (1/2)
2017-01-11 19:51:41,077 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,077 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,078 [Executor task launch worker-0] INFO  executor.Executor - Finished task 1.0 in stage 21.0 (TID 31). 1591 bytes result sent to driver
2017-01-11 19:51:41,078 [task-result-getter-3] INFO  scheduler.TaskSetManager - Finished task 1.0 in stage 21.0 (TID 31) in 4 ms on localhost (2/2)
2017-01-11 19:51:41,078 [task-result-getter-3] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 21.0, whose tasks have all completed, from pool
2017-01-11 19:51:41,078 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ResultStage 21 (count at Vocab.scala:32) finished in 0.012 s
2017-01-11 19:51:41,079 [ScalaTest-main-running-ToolTest] INFO  scheduler.DAGScheduler - Job 5 finished: count at Vocab.scala:32, took 0.045241 s
2017-01-11 19:51:41,082 [ScalaTest-main-running-ToolTest] INFO  spark.SparkContext - Starting job: take at Vocab.scala:36
2017-01-11 19:51:41,083 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 1 is 146 bytes
2017-01-11 19:51:41,083 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 0 is 146 bytes
2017-01-11 19:51:41,083 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 4 is 157 bytes
2017-01-11 19:51:41,084 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 3 is 157 bytes
2017-01-11 19:51:41,084 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 5 is 164 bytes
2017-01-11 19:51:41,084 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 6 is 157 bytes
2017-01-11 19:51:41,085 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Got job 6 (take at Vocab.scala:36) with 1 output partitions
2017-01-11 19:51:41,085 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Final stage: ResultStage 28 (take at Vocab.scala:36)
2017-01-11 19:51:41,085 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Parents of final stage: List(ShuffleMapStage 27)
2017-01-11 19:51:41,085 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Missing parents: List()
2017-01-11 19:51:41,085 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ResultStage 28 (MapPartitionsRDD[48] at sortBy at Vocab.scala:31), which has no missing parents
2017-01-11 19:51:41,086 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_18 stored as values in memory (estimated size 3.5 KB, free 3.5 GB)
2017-01-11 19:51:41,086 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_18_piece0 stored as bytes in memory (estimated size 2026.0 B, free 3.5 GB)
2017-01-11 19:51:41,087 [dispatcher-event-loop-0] INFO  storage.BlockManagerInfo - Added broadcast_18_piece0 in memory on localhost:39435 (size: 2026.0 B, free: 3.5 GB)
2017-01-11 19:51:41,087 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 18 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:41,087 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 1 missing tasks from ResultStage 28 (MapPartitionsRDD[48] at sortBy at Vocab.scala:31)
2017-01-11 19:51:41,087 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 28.0 with 1 tasks
2017-01-11 19:51:41,088 [dispatcher-event-loop-1] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 28.0 (TID 32, localhost, partition 0, NODE_LOCAL, 5139 bytes)
2017-01-11 19:51:41,088 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 28.0 (TID 32)
2017-01-11 19:51:41,089 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 4 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,089 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,090 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 28.0 (TID 32). 2033 bytes result sent to driver
2017-01-11 19:51:41,091 [task-result-getter-0] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 28.0 (TID 32) in 4 ms on localhost (1/1)
2017-01-11 19:51:41,091 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ResultStage 28 (take at Vocab.scala:36) finished in 0.004 s
2017-01-11 19:51:41,091 [task-result-getter-0] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 28.0, whose tasks have all completed, from pool
2017-01-11 19:51:41,091 [ScalaTest-main-running-ToolTest] INFO  scheduler.DAGScheduler - Job 6 finished: take at Vocab.scala:36, took 0.008654 s
2017-01-11 19:51:41,094 [ScalaTest-main-running-ToolTest] INFO  spark.SparkContext - Starting job: take at Vocab.scala:36
2017-01-11 19:51:41,096 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Got job 7 (take at Vocab.scala:36) with 1 output partitions
2017-01-11 19:51:41,096 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Final stage: ResultStage 35 (take at Vocab.scala:36)
2017-01-11 19:51:41,096 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Parents of final stage: List(ShuffleMapStage 34)
2017-01-11 19:51:41,096 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Missing parents: List()
2017-01-11 19:51:41,096 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ResultStage 35 (MapPartitionsRDD[48] at sortBy at Vocab.scala:31), which has no missing parents
2017-01-11 19:51:41,097 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_19 stored as values in memory (estimated size 3.5 KB, free 3.5 GB)
2017-01-11 19:51:41,098 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_19_piece0 stored as bytes in memory (estimated size 2026.0 B, free 3.5 GB)
2017-01-11 19:51:41,098 [dispatcher-event-loop-7] INFO  storage.BlockManagerInfo - Added broadcast_19_piece0 in memory on localhost:39435 (size: 2026.0 B, free: 3.5 GB)
2017-01-11 19:51:41,098 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 19 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:41,098 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 1 missing tasks from ResultStage 35 (MapPartitionsRDD[48] at sortBy at Vocab.scala:31)
2017-01-11 19:51:41,098 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 35.0 with 1 tasks
2017-01-11 19:51:41,099 [dispatcher-event-loop-4] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 35.0 (TID 33, localhost, partition 1, PROCESS_LOCAL, 5139 bytes)
2017-01-11 19:51:41,099 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 35.0 (TID 33)
2017-01-11 19:51:41,100 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,100 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,101 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 35.0 (TID 33). 1470 bytes result sent to driver
2017-01-11 19:51:41,101 [task-result-getter-1] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 35.0 (TID 33) in 3 ms on localhost (1/1)
2017-01-11 19:51:41,101 [task-result-getter-1] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 35.0, whose tasks have all completed, from pool
2017-01-11 19:51:41,101 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ResultStage 35 (take at Vocab.scala:36) finished in 0.003 s
2017-01-11 19:51:41,101 [ScalaTest-main-running-ToolTest] INFO  scheduler.DAGScheduler - Job 7 finished: take at Vocab.scala:36, took 0.007206 s
2017-01-11 19:51:41,121 [ScalaTest-main-running-ToolTest] INFO  output.FileOutputCommitter - File Output Committer Algorithm version is 1
2017-01-11 19:51:41,139 [ScalaTest-main-running-ToolTest] INFO  spark.SparkContext - Starting job: saveAsTextFile at Vocab.scala:47
2017-01-11 19:51:41,140 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Registering RDD 52 (coalesce at Vocab.scala:47)
2017-01-11 19:51:41,140 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Got job 8 (saveAsTextFile at Vocab.scala:47) with 1 output partitions
2017-01-11 19:51:41,140 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Final stage: ResultStage 37 (saveAsTextFile at Vocab.scala:47)
2017-01-11 19:51:41,140 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Parents of final stage: List(ShuffleMapStage 36)
2017-01-11 19:51:41,140 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Missing parents: List(ShuffleMapStage 36)
2017-01-11 19:51:41,140 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ShuffleMapStage 36 (MapPartitionsRDD[52] at coalesce at Vocab.scala:47), which has no missing parents
2017-01-11 19:51:41,141 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_20 stored as values in memory (estimated size 3.4 KB, free 3.5 GB)
2017-01-11 19:51:41,142 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_20_piece0 stored as bytes in memory (estimated size 2.1 KB, free 3.5 GB)
2017-01-11 19:51:41,142 [dispatcher-event-loop-0] INFO  storage.BlockManagerInfo - Added broadcast_20_piece0 in memory on localhost:39435 (size: 2.1 KB, free: 3.5 GB)
2017-01-11 19:51:41,143 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 20 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:41,143 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 1 missing tasks from ShuffleMapStage 36 (MapPartitionsRDD[52] at coalesce at Vocab.scala:47)
2017-01-11 19:51:41,143 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 36.0 with 1 tasks
2017-01-11 19:51:41,143 [dispatcher-event-loop-1] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 36.0 (TID 34, localhost, partition 0, PROCESS_LOCAL, 6098 bytes)
2017-01-11 19:51:41,143 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 36.0 (TID 34)
2017-01-11 19:51:41,148 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 36.0 (TID 34). 1079 bytes result sent to driver
2017-01-11 19:51:41,148 [task-result-getter-2] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 36.0 (TID 34) in 5 ms on localhost (1/1)
2017-01-11 19:51:41,148 [task-result-getter-2] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 36.0, whose tasks have all completed, from pool
2017-01-11 19:51:41,148 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ShuffleMapStage 36 (coalesce at Vocab.scala:47) finished in 0.005 s
2017-01-11 19:51:41,148 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - looking for newly runnable stages
2017-01-11 19:51:41,148 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - running: Set()
2017-01-11 19:51:41,148 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - waiting: Set(ResultStage 37)
2017-01-11 19:51:41,148 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - failed: Set()
2017-01-11 19:51:41,149 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ResultStage 37 (MapPartitionsRDD[56] at saveAsTextFile at Vocab.scala:47), which has no missing parents
2017-01-11 19:51:41,156 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_21 stored as values in memory (estimated size 71.3 KB, free 3.5 GB)
2017-01-11 19:51:41,157 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_21_piece0 stored as bytes in memory (estimated size 25.8 KB, free 3.5 GB)
2017-01-11 19:51:41,157 [dispatcher-event-loop-7] INFO  storage.BlockManagerInfo - Added broadcast_21_piece0 in memory on localhost:39435 (size: 25.8 KB, free: 3.5 GB)
2017-01-11 19:51:41,157 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 21 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:41,157 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 1 missing tasks from ResultStage 37 (MapPartitionsRDD[56] at saveAsTextFile at Vocab.scala:47)
2017-01-11 19:51:41,157 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 37.0 with 1 tasks
2017-01-11 19:51:41,158 [dispatcher-event-loop-4] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 37.0 (TID 35, localhost, partition 0, NODE_LOCAL, 5391 bytes)
2017-01-11 19:51:41,158 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 37.0 (TID 35)
2017-01-11 19:51:41,178 [Executor task launch worker-0] INFO  output.FileOutputCommitter - File Output Committer Algorithm version is 1
2017-01-11 19:51:41,192 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 1 blocks
2017-01-11 19:51:41,192 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,200 [Executor task launch worker-0] INFO  output.FileOutputCommitter - Saved output of task 'attempt_201701111951_0037_m_000000_35' to file:/home/xiaoyzhu/Test2/CaffeOnSpark/caffe-grid/target/coco_vocab/_temporary/0/task_201701111951_0037_m_000000
2017-01-11 19:51:41,200 [Executor task launch worker-0] INFO  mapred.SparkHadoopMapRedUtil - attempt_201701111951_0037_m_000000_35: Committed
2017-01-11 19:51:41,201 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 37.0 (TID 35). 1476 bytes result sent to driver
2017-01-11 19:51:41,201 [task-result-getter-3] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 37.0 (TID 35) in 43 ms on localhost (1/1)
2017-01-11 19:51:41,201 [task-result-getter-3] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 37.0, whose tasks have all completed, from pool
2017-01-11 19:51:41,201 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ResultStage 37 (saveAsTextFile at Vocab.scala:47) finished in 0.043 s
2017-01-11 19:51:41,201 [ScalaTest-main-running-ToolTest] INFO  scheduler.DAGScheduler - Job 8 finished: saveAsTextFile at Vocab.scala:47, took 0.062058 s
2017-01-11 19:51:41,210 [ScalaTest-main-running-ToolTest] INFO  memory.MemoryStore - Block broadcast_22 stored as values in memory (estimated size 229.9 KB, free 3.5 GB)
2017-01-11 19:51:41,219 [ScalaTest-main-running-ToolTest] INFO  memory.MemoryStore - Block broadcast_22_piece0 stored as bytes in memory (estimated size 22.1 KB, free 3.5 GB)
2017-01-11 19:51:41,219 [dispatcher-event-loop-1] INFO  storage.BlockManagerInfo - Added broadcast_22_piece0 in memory on localhost:39435 (size: 22.1 KB, free: 3.5 GB)
2017-01-11 19:51:41,219 [ScalaTest-main-running-ToolTest] INFO  spark.SparkContext - Created broadcast 22 from textFile at Vocab.scala:53
2017-01-11 19:51:41,234 [ScalaTest-main-running-ToolTest] INFO  mapred.FileInputFormat - Total input paths to process : 1
2017-01-11 19:51:41,239 [ScalaTest-main-running-ToolTest] INFO  spark.SparkContext - Starting job: collectAsMap at Vocab.scala:56
2017-01-11 19:51:41,239 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Got job 9 (collectAsMap at Vocab.scala:56) with 1 output partitions
2017-01-11 19:51:41,239 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Final stage: ResultStage 38 (collectAsMap at Vocab.scala:56)
2017-01-11 19:51:41,239 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Parents of final stage: List()
2017-01-11 19:51:41,239 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Missing parents: List()
2017-01-11 19:51:41,239 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ResultStage 38 (MapPartitionsRDD[61] at map at Vocab.scala:56), which has no missing parents
2017-01-11 19:51:41,240 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_23 stored as values in memory (estimated size 3.5 KB, free 3.5 GB)
2017-01-11 19:51:41,241 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_23_piece0 stored as bytes in memory (estimated size 2.0 KB, free 3.5 GB)
2017-01-11 19:51:41,241 [dispatcher-event-loop-2] INFO  storage.BlockManagerInfo - Added broadcast_23_piece0 in memory on localhost:39435 (size: 2.0 KB, free: 3.5 GB)
2017-01-11 19:51:41,242 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 23 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:41,242 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 1 missing tasks from ResultStage 38 (MapPartitionsRDD[61] at map at Vocab.scala:56)
2017-01-11 19:51:41,242 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 38.0 with 1 tasks
2017-01-11 19:51:41,242 [dispatcher-event-loop-3] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 38.0 (TID 36, localhost, partition 0, PROCESS_LOCAL, 5533 bytes)
2017-01-11 19:51:41,242 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 38.0 (TID 36)
2017-01-11 19:51:41,244 [Executor task launch worker-0] INFO  rdd.HadoopRDD - Input split: file:/home/xiaoyzhu/Test2/CaffeOnSpark/caffe-grid/target/coco_vocab/part-00000:0+108
2017-01-11 19:51:41,246 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 38.0 (TID 36). 1473 bytes result sent to driver
2017-01-11 19:51:41,247 [task-result-getter-0] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 38.0 (TID 36) in 5 ms on localhost (1/1)
2017-01-11 19:51:41,247 [task-result-getter-0] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 38.0, whose tasks have all completed, from pool
2017-01-11 19:51:41,247 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ResultStage 38 (collectAsMap at Vocab.scala:56) finished in 0.005 s
2017-01-11 19:51:41,247 [ScalaTest-main-running-ToolTest] INFO  scheduler.DAGScheduler - Job 9 finished: collectAsMap at Vocab.scala:56, took 0.008379 s
2017-01-11 19:51:41,269 [ScalaTest-main-running-ToolTest] INFO  codegen.CodeGenerator - Code generated in 7.142652 ms
2017-01-11 19:51:41,311 [ScalaTest-main-running-ToolTest] INFO  codegen.CodeGenerator - Code generated in 6.953446 ms
2017-01-11 19:51:41,342 [ScalaTest-main-running-ToolTest] INFO  codegen.CodeGenerator - Code generated in 6.834041 ms
2017-01-11 19:51:41,373 [ScalaTest-main-running-ToolTest] INFO  spark.SparkContext - Starting job: take at ToolTest.scala:119
2017-01-11 19:51:41,373 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 1 is 146 bytes
2017-01-11 19:51:41,374 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 3 is 157 bytes
2017-01-11 19:51:41,374 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 0 is 146 bytes
2017-01-11 19:51:41,374 [dag-scheduler-event-loop] INFO  spark.MapOutputTrackerMaster - Size of output statuses for shuffle 4 is 157 bytes
2017-01-11 19:51:41,374 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Got job 10 (take at ToolTest.scala:119) with 1 output partitions
2017-01-11 19:51:41,375 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Final stage: ResultStage 43 (take at ToolTest.scala:119)
2017-01-11 19:51:41,375 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Parents of final stage: List(ShuffleMapStage 42, ShuffleMapStage 40)
2017-01-11 19:51:41,375 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Missing parents: List()
2017-01-11 19:51:41,375 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ResultStage 43 (MapPartitionsRDD[85] at map at ToolTest.scala:119), which has no missing parents
2017-01-11 19:51:41,376 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_24 stored as values in memory (estimated size 14.0 KB, free 3.5 GB)
2017-01-11 19:51:41,377 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_24_piece0 stored as bytes in memory (estimated size 6.9 KB, free 3.5 GB)
2017-01-11 19:51:41,378 [dispatcher-event-loop-6] INFO  storage.BlockManagerInfo - Added broadcast_24_piece0 in memory on localhost:39435 (size: 6.9 KB, free: 3.5 GB)
2017-01-11 19:51:41,378 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 24 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:41,378 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 1 missing tasks from ResultStage 43 (MapPartitionsRDD[85] at map at ToolTest.scala:119)
2017-01-11 19:51:41,378 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 43.0 with 1 tasks
2017-01-11 19:51:41,379 [dispatcher-event-loop-5] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 43.0 (TID 37, localhost, partition 0, PROCESS_LOCAL, 5202 bytes)
2017-01-11 19:51:41,379 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 43.0 (TID 37)
2017-01-11 19:51:41,381 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,381 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,382 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,382 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,383 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 43.0 (TID 37). 1859 bytes result sent to driver
2017-01-11 19:51:41,384 [task-result-getter-1] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 43.0 (TID 37) in 6 ms on localhost (1/1)
2017-01-11 19:51:41,384 [task-result-getter-1] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 43.0, whose tasks have all completed, from pool
2017-01-11 19:51:41,384 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ResultStage 43 (take at ToolTest.scala:119) finished in 0.006 s
2017-01-11 19:51:41,384 [ScalaTest-main-running-ToolTest] INFO  scheduler.DAGScheduler - Job 10 finished: take at ToolTest.scala:119, took 0.011578 s
2017-01-11 19:51:41,388 [ScalaTest-main-running-ToolTest] INFO  spark.SparkContext - Starting job: take at ToolTest.scala:119
2017-01-11 19:51:41,389 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Got job 11 (take at ToolTest.scala:119) with 3 output partitions
2017-01-11 19:51:41,389 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Final stage: ResultStage 48 (take at ToolTest.scala:119)
2017-01-11 19:51:41,389 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Parents of final stage: List(ShuffleMapStage 45, ShuffleMapStage 47)
2017-01-11 19:51:41,389 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Missing parents: List()
2017-01-11 19:51:41,389 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ResultStage 48 (MapPartitionsRDD[85] at map at ToolTest.scala:119), which has no missing parents
2017-01-11 19:51:41,390 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_25 stored as values in memory (estimated size 14.0 KB, free 3.5 GB)
2017-01-11 19:51:41,391 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_25_piece0 stored as bytes in memory (estimated size 6.9 KB, free 3.5 GB)
2017-01-11 19:51:41,392 [dispatcher-event-loop-2] INFO  storage.BlockManagerInfo - Added broadcast_25_piece0 in memory on localhost:39435 (size: 6.9 KB, free: 3.5 GB)
2017-01-11 19:51:41,392 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 25 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:41,392 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 3 missing tasks from ResultStage 48 (MapPartitionsRDD[85] at map at ToolTest.scala:119)
2017-01-11 19:51:41,392 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 48.0 with 3 tasks
2017-01-11 19:51:41,392 [dispatcher-event-loop-3] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 48.0 (TID 38, localhost, partition 1, PROCESS_LOCAL, 5202 bytes)
2017-01-11 19:51:41,393 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 48.0 (TID 38)
2017-01-11 19:51:41,395 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,395 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,395 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,395 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,397 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 48.0 (TID 38). 1859 bytes result sent to driver
2017-01-11 19:51:41,397 [dispatcher-event-loop-4] INFO  scheduler.TaskSetManager - Starting task 1.0 in stage 48.0 (TID 39, localhost, partition 2, PROCESS_LOCAL, 5202 bytes)
2017-01-11 19:51:41,397 [Executor task launch worker-0] INFO  executor.Executor - Running task 1.0 in stage 48.0 (TID 39)
2017-01-11 19:51:41,397 [task-result-getter-2] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 48.0 (TID 38) in 5 ms on localhost (1/3)
2017-01-11 19:51:41,400 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,400 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,400 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,400 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,404 [Executor task launch worker-0] INFO  executor.Executor - Finished task 1.0 in stage 48.0 (TID 39). 1921 bytes result sent to driver
2017-01-11 19:51:41,405 [dispatcher-event-loop-5] INFO  scheduler.TaskSetManager - Starting task 2.0 in stage 48.0 (TID 40, localhost, partition 3, PROCESS_LOCAL, 5202 bytes)
2017-01-11 19:51:41,405 [Executor task launch worker-0] INFO  executor.Executor - Running task 2.0 in stage 48.0 (TID 40)
2017-01-11 19:51:41,405 [task-result-getter-3] INFO  scheduler.TaskSetManager - Finished task 1.0 in stage 48.0 (TID 39) in 8 ms on localhost (2/3)
2017-01-11 19:51:41,408 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,408 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,408 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,408 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,412 [Executor task launch worker-0] INFO  executor.Executor - Finished task 2.0 in stage 48.0 (TID 40). 1918 bytes result sent to driver
2017-01-11 19:51:41,413 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ResultStage 48 (take at ToolTest.scala:119) finished in 0.021 s
2017-01-11 19:51:41,413 [task-result-getter-0] INFO  scheduler.TaskSetManager - Finished task 2.0 in stage 48.0 (TID 40) in 8 ms on localhost (3/3)
2017-01-11 19:51:41,413 [task-result-getter-0] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 48.0, whose tasks have all completed, from pool
2017-01-11 19:51:41,413 [ScalaTest-main-running-ToolTest] INFO  scheduler.DAGScheduler - Job 11 finished: take at ToolTest.scala:119, took 0.024823 s
2017-01-11 19:51:41,422 [ScalaTest-main-running-ToolTest] INFO  codegen.CodeGenerator - Code generated in 5.037778 ms
2017-01-11 19:51:41,435 [ScalaTest-main-running-ToolTest] INFO  spark.SparkContext - Starting job: take at ToolTest.scala:120
2017-01-11 19:51:41,437 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Got job 12 (take at ToolTest.scala:120) with 1 output partitions
2017-01-11 19:51:41,437 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Final stage: ResultStage 53 (take at ToolTest.scala:120)
2017-01-11 19:51:41,437 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Parents of final stage: List(ShuffleMapStage 52, ShuffleMapStage 50)
2017-01-11 19:51:41,437 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Missing parents: List()
2017-01-11 19:51:41,437 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ResultStage 53 (MapPartitionsRDD[90] at map at ToolTest.scala:120), which has no missing parents
2017-01-11 19:51:41,439 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_26 stored as values in memory (estimated size 29.0 KB, free 3.5 GB)
2017-01-11 19:51:41,440 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_26_piece0 stored as bytes in memory (estimated size 11.5 KB, free 3.5 GB)
2017-01-11 19:51:41,440 [dispatcher-event-loop-2] INFO  storage.BlockManagerInfo - Added broadcast_26_piece0 in memory on localhost:39435 (size: 11.5 KB, free: 3.5 GB)
2017-01-11 19:51:41,440 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 26 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:41,440 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 1 missing tasks from ResultStage 53 (MapPartitionsRDD[90] at map at ToolTest.scala:120)
2017-01-11 19:51:41,440 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 53.0 with 1 tasks
2017-01-11 19:51:41,441 [dispatcher-event-loop-3] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 53.0 (TID 41, localhost, partition 0, PROCESS_LOCAL, 5202 bytes)
2017-01-11 19:51:41,441 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 53.0 (TID 41)
2017-01-11 19:51:41,445 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,445 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,445 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,445 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,455 [Executor task launch worker-0] INFO  codegen.CodeGenerator - Code generated in 7.374361 ms
2017-01-11 19:51:41,485 [Executor task launch worker-0] INFO  codegen.CodeGenerator - Code generated in 12.026026 ms
2017-01-11 19:51:41,496 [Executor task launch worker-0] INFO  codegen.CodeGenerator - Code generated in 8.521302 ms
2017-01-11 19:51:41,502 [Executor task launch worker-0] INFO  codegen.CodeGenerator - Code generated in 4.567262 ms
2017-01-11 19:51:41,505 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 53.0 (TID 41). 2163 bytes result sent to driver
2017-01-11 19:51:41,505 [task-result-getter-1] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 53.0 (TID 41) in 64 ms on localhost (1/1)
2017-01-11 19:51:41,505 [task-result-getter-1] INFO  scheduler.TaskSchedulerImpl - Removed TaskSet 53.0, whose tasks have all completed, from pool
2017-01-11 19:51:41,505 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ResultStage 53 (take at ToolTest.scala:120) finished in 0.065 s
2017-01-11 19:51:41,506 [ScalaTest-main-running-ToolTest] INFO  scheduler.DAGScheduler - Job 12 finished: take at ToolTest.scala:120, took 0.070237 s
2017-01-11 19:51:41,511 [ScalaTest-main-running-ToolTest] INFO  spark.SparkContext - Starting job: take at ToolTest.scala:120
2017-01-11 19:51:41,513 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Got job 13 (take at ToolTest.scala:120) with 3 output partitions
2017-01-11 19:51:41,513 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Final stage: ResultStage 58 (take at ToolTest.scala:120)
2017-01-11 19:51:41,513 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Parents of final stage: List(ShuffleMapStage 57, ShuffleMapStage 55)
2017-01-11 19:51:41,513 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Missing parents: List()
2017-01-11 19:51:41,513 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting ResultStage 58 (MapPartitionsRDD[90] at map at ToolTest.scala:120), which has no missing parents
2017-01-11 19:51:41,515 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_27 stored as values in memory (estimated size 29.0 KB, free 3.5 GB)
2017-01-11 19:51:41,516 [dag-scheduler-event-loop] INFO  memory.MemoryStore - Block broadcast_27_piece0 stored as bytes in memory (estimated size 11.5 KB, free 3.5 GB)
2017-01-11 19:51:41,516 [dispatcher-event-loop-6] INFO  storage.BlockManagerInfo - Added broadcast_27_piece0 in memory on localhost:39435 (size: 11.5 KB, free: 3.5 GB)
2017-01-11 19:51:41,516 [dag-scheduler-event-loop] INFO  spark.SparkContext - Created broadcast 27 from broadcast at DAGScheduler.scala:1012
2017-01-11 19:51:41,516 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - Submitting 3 missing tasks from ResultStage 58 (MapPartitionsRDD[90] at map at ToolTest.scala:120)
2017-01-11 19:51:41,516 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Adding task set 58.0 with 3 tasks
2017-01-11 19:51:41,517 [dispatcher-event-loop-5] INFO  scheduler.TaskSetManager - Starting task 0.0 in stage 58.0 (TID 42, localhost, partition 1, PROCESS_LOCAL, 5202 bytes)
2017-01-11 19:51:41,517 [Executor task launch worker-0] INFO  executor.Executor - Running task 0.0 in stage 58.0 (TID 42)
2017-01-11 19:51:41,520 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,520 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,520 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 0 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,520 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,539 [Executor task launch worker-0] INFO  executor.Executor - Finished task 0.0 in stage 58.0 (TID 42). 2163 bytes result sent to driver
2017-01-11 19:51:41,539 [dispatcher-event-loop-1] INFO  scheduler.TaskSetManager - Starting task 1.0 in stage 58.0 (TID 43, localhost, partition 2, PROCESS_LOCAL, 5202 bytes)
2017-01-11 19:51:41,539 [Executor task launch worker-0] INFO  executor.Executor - Running task 1.0 in stage 58.0 (TID 43)
2017-01-11 19:51:41,540 [task-result-getter-2] INFO  scheduler.TaskSetManager - Finished task 0.0 in stage 58.0 (TID 42) in 23 ms on localhost (1/3)
2017-01-11 19:51:41,543 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,543 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,543 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,543 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,599 [Executor task launch worker-0] INFO  codegen.CodeGenerator - Code generated in 30.295871 ms
2017-01-11 19:51:41,617 [Executor task launch worker-0] INFO  codegen.CodeGenerator - Code generated in 9.831747 ms
2017-01-11 19:51:41,623 [Executor task launch worker-0] ERROR executor.Executor - Exception in task 1.0 in stage 58.0 (TID 43)
java.lang.RuntimeException: Error while encoding: java.lang.RuntimeException: java.lang.String is not a valid external type for schema of bigint
if (assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt) null else validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 0, id), LongType) AS id#161L
+- if (assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt) null else validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 0, id), LongType)
   :- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt
   :  :- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object)
   :  :  +- input[0, org.apache.spark.sql.Row, true]
   :  +- 0
   :- null
   +- validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 0, id), LongType)
      +- getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 0, id)
         +- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object)
            +- input[0, org.apache.spark.sql.Row, true]

if (assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt) null else staticinvoke(class org.apache.spark.unsafe.types.UTF8String, StringType, fromString, validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption), StringType), true) AS caption#162
+- if (assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt) null else staticinvoke(class org.apache.spark.unsafe.types.UTF8String, StringType, fromString, validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption), StringType), true)
   :- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt
   :  :- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object)
   :  :  +- input[0, org.apache.spark.sql.Row, true]
   :  +- 1
   :- null
   +- staticinvoke(class org.apache.spark.unsafe.types.UTF8String, StringType, fromString, validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption), StringType), true)
      +- validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption), StringType)
         +- getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption)
            +- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object)
               +- input[0, org.apache.spark.sql.Row, true]

        at org.apache.spark.sql.catalyst.encoders.ExpressionEncoder.toRow(ExpressionEncoder.scala:279)
        at org.apache.spark.sql.SparkSession$$anonfun$5.apply(SparkSession.scala:537)
        at org.apache.spark.sql.SparkSession$$anonfun$5.apply(SparkSession.scala:537)
        at scala.collection.Iterator$$anon$11.next(Iterator.scala:370)
        at scala.collection.Iterator$$anon$11.next(Iterator.scala:370)
        at org.apache.spark.sql.catalyst.expressions.GeneratedClass$GeneratedIterator.processNext(Unknown Source)
        at org.apache.spark.sql.execution.BufferedRowIterator.hasNext(BufferedRowIterator.java:43)
        at org.apache.spark.sql.execution.WholeStageCodegenExec$$anonfun$8$$anon$1.hasNext(WholeStageCodegenExec.scala:370)
        at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:369)
        at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:369)
        at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:369)
        at scala.collection.Iterator$$anon$10.hasNext(Iterator.scala:350)
        at scala.collection.Iterator$class.foreach(Iterator.scala:742)
        at scala.collection.AbstractIterator.foreach(Iterator.scala:1194)
        at scala.collection.generic.Growable$class.$plus$plus$eq(Growable.scala:59)
        at scala.collection.mutable.ArrayBuffer.$plus$plus$eq(ArrayBuffer.scala:104)
        at scala.collection.mutable.ArrayBuffer.$plus$plus$eq(ArrayBuffer.scala:48)
        at scala.collection.TraversableOnce$class.to(TraversableOnce.scala:308)
        at scala.collection.AbstractIterator.to(Iterator.scala:1194)
        at scala.collection.TraversableOnce$class.toBuffer(TraversableOnce.scala:300)
        at scala.collection.AbstractIterator.toBuffer(Iterator.scala:1194)
        at scala.collection.TraversableOnce$class.toArray(TraversableOnce.scala:287)
        at scala.collection.AbstractIterator.toArray(Iterator.scala:1194)
        at org.apache.spark.rdd.RDD$$anonfun$take$1$$anonfun$29.apply(RDD.scala:1305)
        at org.apache.spark.rdd.RDD$$anonfun$take$1$$anonfun$29.apply(RDD.scala:1305)
        at org.apache.spark.SparkContext$$anonfun$runJob$5.apply(SparkContext.scala:1897)
        at org.apache.spark.SparkContext$$anonfun$runJob$5.apply(SparkContext.scala:1897)
        at org.apache.spark.scheduler.ResultTask.runTask(ResultTask.scala:70)
        at org.apache.spark.scheduler.Task.run(Task.scala:85)
        at org.apache.spark.executor.Executor$TaskRunner.run(Executor.scala:274)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.RuntimeException: java.lang.String is not a valid external type for schema of bigint
        at org.apache.spark.sql.catalyst.expressions.GeneratedClass$SpecificUnsafeProjection.apply(Unknown Source)
        at org.apache.spark.sql.catalyst.encoders.ExpressionEncoder.toRow(ExpressionEncoder.scala:276)
        ... 32 more
2017-01-11 19:51:41,636 [dispatcher-event-loop-3] INFO  scheduler.TaskSetManager - Starting task 2.0 in stage 58.0 (TID 44, localhost, partition 3, PROCESS_LOCAL, 5202 bytes)
2017-01-11 19:51:41,636 [Executor task launch worker-0] INFO  executor.Executor - Running task 2.0 in stage 58.0 (TID 44)
2017-01-11 19:51:41,638 [task-result-getter-3] WARN  scheduler.TaskSetManager - Lost task 1.0 in stage 58.0 (TID 43, localhost): java.lang.RuntimeException: Error while encoding: java.lang.RuntimeException: java.lang.String is not a valid external type for schema of bigint
if (assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt) null else validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 0, id), LongType) AS id#161L
+- if (assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt) null else validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 0, id), LongType)
   :- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt
   :  :- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object)
   :  :  +- input[0, org.apache.spark.sql.Row, true]
   :  +- 0
   :- null
   +- validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 0, id), LongType)
      +- getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 0, id)
         +- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object)
            +- input[0, org.apache.spark.sql.Row, true]

if (assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt) null else staticinvoke(class org.apache.spark.unsafe.types.UTF8String, StringType, fromString, validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption), StringType), true) AS caption#162
+- if (assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt) null else staticinvoke(class org.apache.spark.unsafe.types.UTF8String, StringType, fromString, validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption), StringType), true)
   :- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt
   :  :- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object)
   :  :  +- input[0, org.apache.spark.sql.Row, true]
   :  +- 1
   :- null
   +- staticinvoke(class org.apache.spark.unsafe.types.UTF8String, StringType, fromString, validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption), StringType), true)
      +- validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption), StringType)
         +- getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption)
            +- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object)
               +- input[0, org.apache.spark.sql.Row, true]

        at org.apache.spark.sql.catalyst.encoders.ExpressionEncoder.toRow(ExpressionEncoder.scala:279)
        at org.apache.spark.sql.SparkSession$$anonfun$5.apply(SparkSession.scala:537)
        at org.apache.spark.sql.SparkSession$$anonfun$5.apply(SparkSession.scala:537)
        at scala.collection.Iterator$$anon$11.next(Iterator.scala:370)
        at scala.collection.Iterator$$anon$11.next(Iterator.scala:370)
        at org.apache.spark.sql.catalyst.expressions.GeneratedClass$GeneratedIterator.processNext(Unknown Source)
        at org.apache.spark.sql.execution.BufferedRowIterator.hasNext(BufferedRowIterator.java:43)
        at org.apache.spark.sql.execution.WholeStageCodegenExec$$anonfun$8$$anon$1.hasNext(WholeStageCodegenExec.scala:370)
        at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:369)
        at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:369)
        at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:369)
        at scala.collection.Iterator$$anon$10.hasNext(Iterator.scala:350)
        at scala.collection.Iterator$class.foreach(Iterator.scala:742)
        at scala.collection.AbstractIterator.foreach(Iterator.scala:1194)
        at scala.collection.generic.Growable$class.$plus$plus$eq(Growable.scala:59)
        at scala.collection.mutable.ArrayBuffer.$plus$plus$eq(ArrayBuffer.scala:104)
        at scala.collection.mutable.ArrayBuffer.$plus$plus$eq(ArrayBuffer.scala:48)
        at scala.collection.TraversableOnce$class.to(TraversableOnce.scala:308)
        at scala.collection.AbstractIterator.to(Iterator.scala:1194)
        at scala.collection.TraversableOnce$class.toBuffer(TraversableOnce.scala:300)
        at scala.collection.AbstractIterator.toBuffer(Iterator.scala:1194)
        at scala.collection.TraversableOnce$class.toArray(TraversableOnce.scala:287)
        at scala.collection.AbstractIterator.toArray(Iterator.scala:1194)
        at org.apache.spark.rdd.RDD$$anonfun$take$1$$anonfun$29.apply(RDD.scala:1305)
        at org.apache.spark.rdd.RDD$$anonfun$take$1$$anonfun$29.apply(RDD.scala:1305)
        at org.apache.spark.SparkContext$$anonfun$runJob$5.apply(SparkContext.scala:1897)
        at org.apache.spark.SparkContext$$anonfun$runJob$5.apply(SparkContext.scala:1897)
        at org.apache.spark.scheduler.ResultTask.runTask(ResultTask.scala:70)
        at org.apache.spark.scheduler.Task.run(Task.scala:85)
        at org.apache.spark.executor.Executor$TaskRunner.run(Executor.scala:274)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.RuntimeException: java.lang.String is not a valid external type for schema of bigint
        at org.apache.spark.sql.catalyst.expressions.GeneratedClass$SpecificUnsafeProjection.apply(Unknown Source)
        at org.apache.spark.sql.catalyst.encoders.ExpressionEncoder.toRow(ExpressionEncoder.scala:276)
        ... 32 more

2017-01-11 19:51:41,639 [task-result-getter-3] ERROR scheduler.TaskSetManager - Task 1 in stage 58.0 failed 1 times; aborting job
2017-01-11 19:51:41,640 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,640 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,641 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Getting 1 non-empty blocks out of 4 blocks
2017-01-11 19:51:41,641 [Executor task launch worker-0] INFO  storage.ShuffleBlockFetcherIterator - Started 0 remote fetches in 0 ms
2017-01-11 19:51:41,643 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Cancelling stage 58
2017-01-11 19:51:41,644 [dag-scheduler-event-loop] INFO  scheduler.TaskSchedulerImpl - Stage 58 was cancelled
2017-01-11 19:51:41,644 [dispatcher-event-loop-4] INFO  executor.Executor - Executor is trying to kill task 2.0 in stage 58.0 (TID 44)
2017-01-11 19:51:41,645 [dag-scheduler-event-loop] INFO  scheduler.DAGScheduler - ResultStage 58 (take at ToolTest.scala:120) failed in 0.129 s
2017-01-11 19:51:41,646 [ScalaTest-main-running-ToolTest] INFO  scheduler.DAGScheduler - Job 13 failed: take at ToolTest.scala:120, took 0.134317 s
- CocoTest *** FAILED ***
  org.apache.spark.SparkException: Job aborted due to stage failure: Task 1 in stage 58.0 failed 1 times, most recent failure: Lost task 1.0 in stage 58.0 (TID 43, localhost): java.lang.RuntimeException: Error while encoding: java.lang.RuntimeException: java.lang.String is not a valid external type for schema of bigint
if (assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt) null else validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 0, id), LongType) AS id#161L
+- if (assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt) null else validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 0, id), LongType)
   :- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt
   :  :- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object)
   :  :  +- input[0, org.apache.spark.sql.Row, true]
   :  +- 0
   :- null
   +- validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 0, id), LongType)
      +- getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 0, id)
         +- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object)
            +- input[0, org.apache.spark.sql.Row, true]

if (assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt) null else staticinvoke(class org.apache.spark.unsafe.types.UTF8String, StringType, fromString, validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption), StringType), true) AS caption#162
+- if (assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt) null else staticinvoke(class org.apache.spark.unsafe.types.UTF8String, StringType, fromString, validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption), StringType), true)
   :- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt
   :  :- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object)
   :  :  +- input[0, org.apache.spark.sql.Row, true]
   :  +- 1
   :- null
   +- staticinvoke(class org.apache.spark.unsafe.types.UTF8String, StringType, fromString, validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption), StringType), true)
      +- validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption), StringType)
         +- getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption)
            +- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object)
               +- input[0, org.apache.spark.sql.Row, true]

        at org.apache.spark.sql.catalyst.encoders.ExpressionEncoder.toRow(ExpressionEncoder.scala:279)
        at org.apache.spark.sql.SparkSession$$anonfun$5.apply(SparkSession.scala:537)
        at org.apache.spark.sql.SparkSession$$anonfun$5.apply(SparkSession.scala:537)
        at scala.collection.Iterator$$anon$11.next(Iterator.scala:370)
        at scala.collection.Iterator$$anon$11.next(Iterator.scala:370)
        at org.apache.spark.sql.catalyst.expressions.GeneratedClass$GeneratedIterator.processNext(Unknown Source)
        at org.apache.spark.sql.execution.BufferedRowIterator.hasNext(BufferedRowIterator.java:43)
        at org.apache.spark.sql.execution.WholeStageCodegenExec$$anonfun$8$$anon$1.hasNext(WholeStageCodegenExec.scala:370)
        at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:369)
        at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:369)
        at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:369)
        at scala.collection.Iterator$$anon$10.hasNext(Iterator.scala:350)
        at scala.collection.Iterator$class.foreach(Iterator.scala:742)
        at scala.collection.AbstractIterator.foreach(Iterator.scala:1194)
        at scala.collection.generic.Growable$class.$plus$plus$eq(Growable.scala:59)
        at scala.collection.mutable.ArrayBuffer.$plus$plus$eq(ArrayBuffer.scala:104)
        at scala.collection.mutable.ArrayBuffer.$plus$plus$eq(ArrayBuffer.scala:48)
        at scala.collection.TraversableOnce$class.to(TraversableOnce.scala:308)
        at scala.collection.AbstractIterator.to(Iterator.scala:1194)
        at scala.collection.TraversableOnce$class.toBuffer(TraversableOnce.scala:300)
        at scala.collection.AbstractIterator.toBuffer(Iterator.scala:1194)
        at scala.collection.TraversableOnce$class.toArray(TraversableOnce.scala:287)
        at scala.collection.AbstractIterator.toArray(Iterator.scala:1194)
        at org.apache.spark.rdd.RDD$$anonfun$take$1$$anonfun$29.apply(RDD.scala:1305)
        at org.apache.spark.rdd.RDD$$anonfun$take$1$$anonfun$29.apply(RDD.scala:1305)
        at org.apache.spark.SparkContext$$anonfun$runJob$5.apply(SparkContext.scala:1897)
        at org.apache.spark.SparkContext$$anonfun$runJob$5.apply(SparkContext.scala:1897)
        at org.apache.spark.scheduler.ResultTask.runTask(ResultTask.scala:70)
        at org.apache.spark.scheduler.Task.run(Task.scala:85)
        at org.apache.spark.executor.Executor$TaskRunner.run(Executor.scala:274)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.RuntimeException: java.lang.String is not a valid external type for schema of bigint
        at org.apache.spark.sql.catalyst.expressions.GeneratedClass$SpecificUnsafeProjection.apply(Unknown Source)
        at org.apache.spark.sql.catalyst.encoders.ExpressionEncoder.toRow(ExpressionEncoder.scala:276)
        ... 32 more

Driver stacktrace:
  at org.apache.spark.scheduler.DAGScheduler.org$apache$spark$scheduler$DAGScheduler$$failJobAndIndependentStages(DAGScheduler.scala:1450)
  at org.apache.spark.scheduler.DAGScheduler$$anonfun$abortStage$1.apply(DAGScheduler.scala:1438)
  at org.apache.spark.scheduler.DAGScheduler$$anonfun$abortStage$1.apply(DAGScheduler.scala:1437)
  at scala.collection.mutable.ResizableArray$class.foreach(ResizableArray.scala:59)
  at scala.collection.mutable.ArrayBuffer.foreach(ArrayBuffer.scala:48)
  at org.apache.spark.scheduler.DAGScheduler.abortStage(DAGScheduler.scala:1437)
  at org.apache.spark.scheduler.DAGScheduler$$anonfun$handleTaskSetFailed$1.apply(DAGScheduler.scala:811)
  at org.apache.spark.scheduler.DAGScheduler$$anonfun$handleTaskSetFailed$1.apply(DAGScheduler.scala:811)
  at scala.Option.foreach(Option.scala:257)
  at org.apache.spark.scheduler.DAGScheduler.handleTaskSetFailed(DAGScheduler.scala:811)
  ...
  Cause: java.lang.RuntimeException: Error while encoding: java.lang.RuntimeException: java.lang.String is not a valid external type for schema of bigint
if (assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt) null else validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 0, id), LongType) AS id#161L
+- if (assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt) null else validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 0, id), LongType)
   :- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt
   :  :- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object)
   :  :  +- input[0, org.apache.spark.sql.Row, true]
   :  +- 0
   :- null
   +- validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 0, id), LongType)
      +- getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 0, id)
         +- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object)
            +- input[0, org.apache.spark.sql.Row, true]

if (assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt) null else staticinvoke(class org.apache.spark.unsafe.types.UTF8String, StringType, fromString, validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption), StringType), true) AS caption#162
+- if (assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt) null else staticinvoke(class org.apache.spark.unsafe.types.UTF8String, StringType, fromString, validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption), StringType), true)
   :- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object).isNullAt
   :  :- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object)
   :  :  +- input[0, org.apache.spark.sql.Row, true]
   :  +- 1
   :- null
   +- staticinvoke(class org.apache.spark.unsafe.types.UTF8String, StringType, fromString, validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption), StringType), true)
      +- validateexternaltype(getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption), StringType)
         +- getexternalrowfield(assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object), 1, caption)
            +- assertnotnull(input[0, org.apache.spark.sql.Row, true], top level row object)
               +- input[0, org.apache.spark.sql.Row, true]
  at org.apache.spark.sql.catalyst.encoders.ExpressionEncoder.toRow(ExpressionEncoder.scala:279)
  at org.apache.spark.sql.SparkSession$$anonfun$5.apply(SparkSession.scala:537)
  at org.apache.spark.sql.SparkSession$$anonfun$5.apply(SparkSession.scala:537)
  at scala.collection.Iterator$$anon$11.next(Iterator.scala:370)
  at scala.collection.Iterator$$anon$11.next(Iterator.scala:370)
  at org.apache.spark.sql.catalyst.expressions.GeneratedClass$GeneratedIterator.processNext(Unknown Source)
  at org.apache.spark.sql.execution.BufferedRowIterator.hasNext(BufferedRowIterator.java:43)
  at org.apache.spark.sql.execution.WholeStageCodegenExec$$anonfun$8$$anon$1.hasNext(WholeStageCodegenExec.scala:370)
  at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:369)
  at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:369)
  ...
  Cause: java.lang.RuntimeException: java.lang.String is not a valid external type for schema of bigint
  at org.apache.spark.sql.catalyst.expressions.GeneratedClass$SpecificUnsafeProjection.apply(Unknown Source)
  at org.apache.spark.sql.catalyst.encoders.ExpressionEncoder.toRow(ExpressionEncoder.scala:276)
  at org.apache.spark.sql.SparkSession$$anonfun$5.apply(SparkSession.scala:537)
  at org.apache.spark.sql.SparkSession$$anonfun$5.apply(SparkSession.scala:537)
  at scala.collection.Iterator$$anon$11.next(Iterator.scala:370)
  at scala.collection.Iterator$$anon$11.next(Iterator.scala:370)
  at org.apache.spark.sql.catalyst.expressions.GeneratedClass$GeneratedIterator.processNext(Unknown Source)
  at org.apache.spark.sql.execution.BufferedRowIterator.hasNext(BufferedRowIterator.java:43)
  at org.apache.spark.sql.execution.WholeStageCodegenExec$$anonfun$8$$anon$1.hasNext(WholeStageCodegenExec.scala:370)
  at scala.collection.Iterator$$anon$11.hasNext(Iterator.scala:369)
  ...
2017-01-11 19:51:41,657 [ScalaTest-main-running-DiscoverySuite] INFO  server.ServerConnector - Stopped ServerConnector@3dded90a{HTTP/1.1}{0.0.0.0:4040}
2017-01-11 19:51:41,657 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@720c8f80{/stages/stage/kill,null,UNAVAILABLE}
2017-01-11 19:51:41,657 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@e6e5da4{/api,null,UNAVAILABLE}
2017-01-11 19:51:41,657 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@1dcca426{/,null,UNAVAILABLE}
2017-01-11 19:51:41,657 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@7a30e30b{/static,null,UNAVAILABLE}
2017-01-11 19:51:41,657 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@4377ed24{/executors/threadDump/json,null,UNAVAILABLE}
2017-01-11 19:51:41,657 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@45eacb70{/executors/threadDump,null,UNAVAILABLE}
2017-01-11 19:51:41,658 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@77020328{/executors/json,null,UNAVAILABLE}
2017-01-11 19:51:41,658 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@407f2029{/executors,null,UNAVAILABLE}
2017-01-11 19:51:41,658 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@28b5d5dc{/environment/json,null,UNAVAILABLE}
2017-01-11 19:51:41,658 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@6b3b2c34{/environment,null,UNAVAILABLE}
2017-01-11 19:51:41,658 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@3b01897f{/storage/rdd/json,null,UNAVAILABLE}
2017-01-11 19:51:41,658 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@72f35a31{/storage/rdd,null,UNAVAILABLE}
2017-01-11 19:51:41,658 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@478089b6{/storage/json,null,UNAVAILABLE}
2017-01-11 19:51:41,658 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@3eedd0e3{/storage,null,UNAVAILABLE}
2017-01-11 19:51:41,658 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@f08d676{/stages/pool/json,null,UNAVAILABLE}
2017-01-11 19:51:41,658 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@7b29cdea{/stages/pool,null,UNAVAILABLE}
2017-01-11 19:51:41,658 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@6bc25ac2{/stages/stage/json,null,UNAVAILABLE}
2017-01-11 19:51:41,659 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@7e89eba7{/stages/stage,null,UNAVAILABLE}
2017-01-11 19:51:41,659 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@305881b8{/stages/json,null,UNAVAILABLE}
2017-01-11 19:51:41,659 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@7b2e931{/stages,null,UNAVAILABLE}
2017-01-11 19:51:41,659 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@775c4054{/jobs/job/json,null,UNAVAILABLE}
2017-01-11 19:51:41,659 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@68c4db77{/jobs/job,null,UNAVAILABLE}
2017-01-11 19:51:41,659 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@2c7375da{/jobs/json,null,UNAVAILABLE}
2017-01-11 19:51:41,659 [ScalaTest-main-running-DiscoverySuite] INFO  handler.ContextHandler - Stopped o.s.j.s.ServletContextHandler@681311a7{/jobs,null,UNAVAILABLE}
2017-01-11 19:51:41,660 [ScalaTest-main-running-DiscoverySuite] INFO  ui.SparkUI - Stopped Spark web UI at http://localhost:4040
2017-01-11 19:51:41,662 [dispatcher-event-loop-6] INFO  spark.MapOutputTrackerMasterEndpoint - MapOutputTrackerMasterEndpoint stopped!
2017-01-11 19:51:41,665 [Executor task launch worker-0] INFO  executor.Executor - Executor killed task 2.0 in stage 58.0 (TID 44)
2017-01-11 19:51:41,667 [ScalaTest-main-running-DiscoverySuite] INFO  memory.MemoryStore - MemoryStore cleared
2017-01-11 19:51:41,667 [ScalaTest-main-running-DiscoverySuite] INFO  storage.BlockManager - BlockManager stopped
2017-01-11 19:51:41,667 [ScalaTest-main-running-DiscoverySuite] INFO  storage.BlockManagerMaster - BlockManagerMaster stopped
2017-01-11 19:51:41,668 [dispatcher-event-loop-4] INFO  scheduler.OutputCommitCoordinator$OutputCommitCoordinatorEndpoint - OutputCommitCoordinator stopped!
2017-01-11 19:51:41,670 [ScalaTest-main-running-DiscoverySuite] INFO  spark.SparkContext - Successfully stopped SparkContext
Jan 11 '17 19:01 xiaoyongzhu
This is the result - 6 successful and 1 failed. The environment is:
Hadoop 2.7.1, Spark 2.0.1, Java 8, Ubuntu 16.04, Scala 2.11
Run completed in 32 seconds, 78 milliseconds. Total number of tests run: 7 Suites: completed 5, aborted 0 Tests: succeeded 6, failed 1, canceled 0, ignored 0, pending 0 *** 1 TEST FAILED ***
Jan 11 '17 20:01 xiaoyongzhu
It may be related to UTF-8 encoding. We are not able to duplicate the error, but multiple users reported this issue.
Jan 11 '17 23:01 junshi15
@junshi15 I can help to provide you the environment if it helps. It is on public cloud so I can share the credential with you offline. You can get to me via xiaoyzhu at microsoft dot com.
Jan 12 '17 01:01 xiaoyongzhu
I tested on Ubuntu 14.04 with scala-2.10.6 and spark 1.6.0, it worked. then I saw problems with a python test with scala-2.11.7 and spark 2.0.0, not the same problem as yours. So there is a compatibility issue with the newer scala/spark versions. But we don't use either of those in our production, so support of those will be limited. You are welcome to send a pull-request.
Jan 13 '17 15:01 junshi15
skip test.
Mar 31 '17 02:03 guyang88
CaffeOnSpark CaffeOnSpark copied to clipboard

Test failure when building Caffe on Spark

CaffeOnSpark
CaffeOnSpark copied to clipboard
