microsoft / microsoft/SynapseML

mmlspark 0.17 : java.lang.NullPointerException: Value at index 4 is null

Open
#679 15 comments 0 reactions 1 assignee View on GitHub

@imatiach-msft is already working on this.

Since Sep 11, 2019.

area/lightgbm
Dominant language
Scala
Stars
5.2k
Forks
868
Avg merge
22h 9m
Merged PRs (30d)
45

Description

I have been facing NullPointerException mentioned above followed by 'Connection refused' error. It seems like connections are being closed to executors before finishing all the tasks. Can you please look into this?

  • MMLSpark Version: [v0.17]
  • Spark Version [2.3.0]

I am running in cluster mode with spark-submit command and dynamic allocation enabled.
** Stacktrace**

2019-08-30 22:07:55 INFO  FairSchedulableBuilder:54 - Added task set TaskSet_183.0 tasks to pool default
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 0.0 in stage 183.0 (TID 6374, JMNGDBAE230C07, executor 9, partition 0, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 1.0 in stage 183.0 (TID 6375, JMNGD1BAE210V10, executor 5, partition 1, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 2.0 in stage 183.0 (TID 6376, JMNGD1BAF070C08, executor 1, partition 2, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 3.0 in stage 183.0 (TID 6377, JMNGD1BAE050V03, executor 4, partition 3, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 4.0 in stage 183.0 (TID 6378, JMNGD1BAE050V03, executor 16, partition 4, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 5.0 in stage 183.0 (TID 6379, JMNGD1BAE210V10, executor 11, partition 5, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 6.0 in stage 183.0 (TID 6380, JMNGD1BAE170V10, executor 7, partition 6, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 7.0 in stage 183.0 (TID 6381, JMNGD1BAE050V03, executor 10, partition 7, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 8.0 in stage 183.0 (TID 6382, JMNGD1BAE050V04, executor 6, partition 8, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 9.0 in stage 183.0 (TID 6383, JMNGD1BAG070C09, executor 20, partition 9, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 10.0 in stage 183.0 (TID 6384, JMNGD1BAE050V04, executor 18, partition 10, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 11.0 in stage 183.0 (TID 6385, JMNGD1BAE170V10, executor 19, partition 11, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 12.0 in stage 183.0 (TID 6386, JMNGD1BAE170V10, executor 13, partition 12, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 13.0 in stage 183.0 (TID 6387, JMNGD1BAE050V04, executor 12, partition 13, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 14.0 in stage 183.0 (TID 6388, JMNGD1BAG70C07, executor 2, partition 14, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 15.0 in stage 183.0 (TID 6389, JMNGDBAE230C07, executor 15, partition 15, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 16.0 in stage 183.0 (TID 6390, JMNGD1BAE050V03, executor 3, partition 16, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 17.0 in stage 183.0 (TID 6391, JMNGD1BAG070C09, executor 14, partition 17, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 18.0 in stage 183.0 (TID 6392, JMNGD1BAE210V10, executor 17, partition 18, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Starting task 19.0 in stage 183.0 (TID 6393, JMNGD1BAG070C08, executor 8, partition 19, PROCESS_LOCAL, 7730 bytes)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGD1BAG70C07:39516 (size: 4.6 KB, free: 1685.1 MB)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGD1BAF070C08:35074 (size: 4.6 KB, free: 1684.9 MB)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGD1BAE210V10:35229 (size: 4.6 KB, free: 1677.6 MB)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGD1BAE050V04:34487 (size: 4.6 KB, free: 1685.0 MB)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGD1BAE050V04:33947 (size: 4.6 KB, free: 1685.1 MB)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGD1BAE170V10:38038 (size: 4.6 KB, free: 1685.1 MB)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGD1BAE050V04:32928 (size: 4.6 KB, free: 1685.0 MB)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGD1BAE210V10:35889 (size: 4.6 KB, free: 1683.4 MB)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGD1BAE170V10:35078 (size: 4.6 KB, free: 1685.1 MB)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGDBAE230C07:45082 (size: 4.6 KB, free: 1685.0 MB)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGD1BAE170V10:41743 (size: 4.6 KB, free: 1685.0 MB)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGD1BAE050V03:45574 (size: 4.6 KB, free: 1592.4 MB)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGD1BAE050V03:43273 (size: 4.6 KB, free: 1607.9 MB)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGD1BAE210V10:43736 (size: 4.6 KB, free: 1683.0 MB)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGDBAE230C07:44691 (size: 4.6 KB, free: 1685.1 MB)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGD1BAE050V03:38066 (size: 4.6 KB, free: 1589.7 MB)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGD1BAE050V03:34388 (size: 4.6 KB, free: 1585.7 MB)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGD1BAG070C08:42414 (size: 4.6 KB, free: 1685.1 MB)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGD1BAG070C09:37013 (size: 4.6 KB, free: 1685.1 MB)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Finished task 14.0 in stage 183.0 (TID 6388) in 41 ms on JMNGD1BAG70C07 (executor 2) (1/20)
2019-08-30 22:07:55 INFO  BlockManagerInfo:54 - Added broadcast_123_piece0 in memory on JMNGD1BAG070C09:34268 (size: 4.6 KB, free: 1685.1 MB)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Finished task 2.0 in stage 183.0 (TID 6376) in 67 ms on JMNGD1BAF070C08 (executor 1) (2/20)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Finished task 1.0 in stage 183.0 (TID 6375) in 69 ms on JMNGD1BAE210V10 (executor 5) (3/20)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Finished task 10.0 in stage 183.0 (TID 6384) in 52 ms on JMNGD1BAE050V04 (executor 18) (4/20)
2019-08-30 22:07:55 INFO  TaskSetManager:54 - Finished task 13.0 in stage 183.0 (TID 6387) in 45 ms on JMNGD1BAE050V04 (executor 12) (5/20)
2019-08-30 22:07:56 INFO  TaskSetManager:54 - Finished task 12.0 in stage 183.0 (TID 6386) in 48 ms on JMNGD1BAE170V10 (executor 13) (6/20)
2019-08-30 22:07:56 INFO  TaskSetManager:54 - Finished task 8.0 in stage 183.0 (TID 6382) in 58 ms on JMNGD1BAE050V04 (executor 6) (7/20)
2019-08-30 22:07:56 INFO  TaskSetManager:54 - Finished task 18.0 in stage 183.0 (TID 6392) in 36 ms on JMNGD1BAE210V10 (executor 17) (8/20)
2019-08-30 22:07:56 INFO  TaskSetManager:54 - Finished task 6.0 in stage 183.0 (TID 6380) in 62 ms on JMNGD1BAE170V10 (executor 7) (9/20)
2019-08-30 22:07:56 INFO  TaskSetManager:54 - Finished task 11.0 in stage 183.0 (TID 6385) in 52 ms on JMNGD1BAE170V10 (executor 19) (10/20)
2019-08-30 22:07:56 INFO  TaskSetManager:54 - Finished task 3.0 in stage 183.0 (TID 6377) in 69 ms on JMNGD1BAE050V03 (executor 4) (11/20)
2019-08-30 22:07:56 INFO  TaskSetManager:54 - Finished task 15.0 in stage 183.0 (TID 6389) in 52 ms on JMNGDBAE230C07 (executor 15) (12/20)
2019-08-30 22:07:56 INFO  TaskSetManager:54 - Finished task 0.0 in stage 183.0 (TID 6374) in 84 ms on JMNGDBAE230C07 (executor 9) (13/20)
2019-08-30 22:07:56 INFO  TaskSetManager:54 - Finished task 16.0 in stage 183.0 (TID 6390) in 51 ms on JMNGD1BAE050V03 (executor 3) (14/20)
2019-08-30 22:07:56 INFO  TaskSetManager:54 - Finished task 4.0 in stage 183.0 (TID 6378) in 77 ms on JMNGD1BAE050V03 (executor 16) (15/20)
2019-08-30 22:07:56 INFO  TaskSetManager:54 - Finished task 9.0 in stage 183.0 (TID 6383) in 67 ms on JMNGD1BAG070C09 (executor 20) (16/20)
2019-08-30 22:07:56 INFO  TaskSetManager:54 - Finished task 7.0 in stage 183.0 (TID 6381) in 71 ms on JMNGD1BAE050V03 (executor 10) (17/20)
2019-08-30 22:07:56 INFO  TaskSetManager:54 - Finished task 19.0 in stage 183.0 (TID 6393) in 45 ms on JMNGD1BAG070C08 (executor 8) (18/20)
2019-08-30 22:07:56 INFO  TaskSetManager:54 - Finished task 5.0 in stage 183.0 (TID 6379) in 76 ms on JMNGD1BAE210V10 (executor 11) (19/20)
2019-08-30 22:07:56 INFO  TaskSetManager:54 - Finished task 17.0 in stage 183.0 (TID 6391) in 52 ms on JMNGD1BAG070C09 (executor 14) (20/20)
2019-08-30 22:07:56 INFO  YarnClusterScheduler:54 - Removed TaskSet 183.0, whose tasks have all completed, from pool default
2019-08-30 22:07:56 INFO  DAGScheduler:54 - ResultStage 183 (collect at LightGBMUtils.scala:183) finished in 0.095 s
2019-08-30 22:07:56 INFO  DAGScheduler:54 - Job 75 finished: collect at LightGBMUtils.scala:183, took 0.097195 s
2019-08-30 22:07:56 INFO  LightGBMRegressor:110 - driver expecting 1 connections...
2019-08-30 22:07:56 INFO  LightGBMRegressor:112 - driver accepting a new connection...
2019-08-30 22:07:56 INFO  LightGBMRegressor:140 - driver waiting for connections on host: 10.144.96.175 and port: 35258
2019-08-30 22:07:56 INFO  LightGBMRegressor:42 - LightGBM parameters: alpha=0.9 tweedie_variance_power=1.5 is_pre_partition=True boosting_type=gbdt tree_learner=data_parallel num_iterations=500 learning_rate=0.1 num_leaves=5 max_bin=255 bagging_fraction=0.8999999761581421 bagging_freq=0 bagging_seed=10011993 early_stopping_round=50 feature_fraction=0.8 max_depth=4 min_sum_hessian_in_leaf=10.0 num_machines=1 objective=regression verbosity=3 boost_from_average=true lambda_l1=0.0 lambda_l2=0.0 
2019-08-30 22:07:56 INFO  SparkContext:54 - Starting job: reduce at LightGBMBase.scala:51
2019-08-30 22:07:56 INFO  DAGScheduler:54 - Got job 76 (reduce at LightGBMBase.scala:51) with 1 output partitions
2019-08-30 22:07:56 INFO  DAGScheduler:54 - Final stage: ResultStage 187 (reduce at LightGBMBase.scala:51)
2019-08-30 22:07:56 INFO  DAGScheduler:54 - Parents of final stage: List(ShuffleMapStage 186)
2019-08-30 22:07:56 INFO  DAGScheduler:54 - Missing parents: List()
2019-08-30 22:07:56 INFO  DAGScheduler:54 - Submitting ResultStage 187 (MapPartitionsRDD[709] at reduce at LightGBMBase.scala:51), which has no missing parents
2019-08-30 22:07:56 INFO  MemoryStore:54 - Block broadcast_124 stored as values in memory (estimated size 26.1 KB, free 3.5 GB)
2019-08-30 22:07:56 INFO  MemoryStore:54 - Block broadcast_124_piece0 stored as bytes in memory (estimated size 12.2 KB, free 3.5 GB)
2019-08-30 22:07:56 INFO  BlockManagerInfo:54 - Added broadcast_124_piece0 in memory on JMNGD1BAE210V10:36083 (size: 12.2 KB, free: 3.6 GB)
2019-08-30 22:07:56 INFO  SparkContext:54 - Created broadcast 124 from broadcast at DAGScheduler.scala:1039
2019-08-30 22:07:56 INFO  DAGScheduler:54 - Submitting 1 missing tasks from ResultStage 187 (MapPartitionsRDD[709] at reduce at LightGBMBase.scala:51) (first 15 tasks are for partitions Vector(0))
2019-08-30 22:07:56 INFO  YarnClusterScheduler:54 - Adding task set 187.0 with 1 tasks
2019-08-30 22:07:56 INFO  FairSchedulableBuilder:54 - Added task set TaskSet_187.0 tasks to pool default
2019-08-30 22:07:56 INFO  TaskSetManager:54 - Starting task 0.0 in stage 187.0 (TID 6394, JMNGD1BAE210V10, executor 11, partition 0, NODE_LOCAL, 8128 bytes)
2019-08-30 22:07:56 INFO  BlockManagerInfo:54 - Added broadcast_124_piece0 in memory on JMNGD1BAE210V10:43736 (size: 12.2 KB, free: 1683.0 MB)
2019-08-30 22:07:56 INFO  LightGBMRegressor:120 - driver received socket from worker: 10.144.96.175:12488
2019-08-30 22:07:56 INFO  LightGBMRegressor:127 - driver writing back to all connections: 10.144.96.175:12488
2019-08-30 22:07:56 INFO  LightGBMRegressor:134 - driver closing all sockets and server socket
2019-08-30 22:07:56 WARN  TaskSetManager:66 - Lost task 0.0 in stage 187.0 (TID 6394, JMNGD1BAE210V10, executor 11): java.lang.NullPointerException: Value at index 4 is null
	at org.apache.spark.sql.Row$class.getAnyValAs(Row.scala:472)
	at org.apache.spark.sql.Row$class.getDouble(Row.scala:248)
	at org.apache.spark.sql.catalyst.expressions.GenericRow.getDouble(rows.scala:166)
	at com.microsoft.ml.spark.TrainUtils$$anonfun$generateDataset$1$$anonfun$6.apply(TrainUtils.scala:64)
	at com.microsoft.ml.spark.TrainUtils$$anonfun$generateDataset$1$$anonfun$6.apply(TrainUtils.scala:64)
	at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:234)
	at scala.collection.TraversableLike$$anonfun$map$1.apply(TraversableLike.scala:234)
	at scala.collection.IndexedSeqOptimized$class.foreach(IndexedSeqOptimized.scala:33)
	at scala.collection.mutable.ArrayOps$ofRef.foreach(ArrayOps.scala:186)
	at scala.collection.TraversableLike$class.map(TraversableLike.scala:234)
	at scala.collection.mutable.ArrayOps$ofRef.map(ArrayOps.scala:186)
	at com.microsoft.ml.spark.TrainUtils$.generateDataset(TrainUtils.scala:63)
	at com.microsoft.ml.spark.TrainUtils$.translate(TrainUtils.scala:168)
	at com.microsoft.ml.spark.TrainUtils$.trainLightGBM(TrainUtils.scala:316)
	at com.microsoft.ml.spark.LightGBMBase$$anonfun$4.apply(LightGBMBase.scala:49)
	at com.microsoft.ml.spark.LightGBMBase$$anonfun$4.apply(LightGBMBase.scala:49)
	at org.apache.spark.sql.execution.MapPartitionsExec$$anonfun$5.apply(objects.scala:188)
	at org.apache.spark.sql.execution.MapPartitionsExec$$anonfun$5.apply(objects.scala:185)
	at org.apache.spark.rdd.RDD$$anonfun$mapPartitionsInternal$1$$anonfun$apply$25.apply(RDD.scala:830)
	at org.apache.spark.rdd.RDD$$anonfun$mapPartitionsInternal$1$$anonfun$apply$25.apply(RDD.scala:830)
	at org.apache.spark.rdd.MapPartitionsRDD.compute(MapPartitionsRDD.scala:38)
	at org.apache.spark.rdd.RDD.computeOrReadCheckpoint(RDD.scala:324)
	at org.apache.spark.rdd.RDD.iterator(RDD.scala:288)
	at org.apache.spark.rdd.MapPartitionsRDD.compute(MapPartitionsRDD.scala:38)
	at org.apache.spark.rdd.RDD.computeOrReadCheckpoint(RDD.scala:324)
	at org.apache.spark.rdd.RDD.iterator(RDD.scala:288)
	at org.apache.spark.scheduler.ResultTask.runTask(ResultTask.scala:87)
	at org.apache.spark.scheduler.Task.run(Task.scala:109)
	at org.apache.spark.executor.Executor$TaskRunner.run(Executor.scala:345)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

If the bug pertains to a specific feature please tag the appropriate CODEOWNER for better visibility

Additional context
Add any other context about the problem here.

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.