Re: problem for mark stage finished?

[Tathagata Das <td...@databricks.com>]

Off the top of my head, I am not sure if this is a known problem. Could try
running the latest Spark (1.3.1 or even better 1.4.0 RC2 that is being
voted) and test whether the problem persists?

TD

On Wed, May 27, 2015 at 5:33 AM, 邓刚[技术中心] <tr...@vipshop.com> wrote:

>  Anyone could take a look at this ?
>
>
>
> *发件人:* 邓刚[技术中心]
> *发送时间:* 2015年5月25日 15:05
> *收件人:* 'dev@spark.apache.org'; 'user'
> *主题:* task all finished, while the stage marked finish long time later
> problem
>
>
>
> Hi All
>
>
>
> As searched the log and the code. We found the hints below (we are using
> spark streaming 1.1.1):
>
>
>
> 1 . our streaming batch is divide by the stage named mapToPair at
> TraceCalculator.java:158(is marked below with red), in the picture below
> the stage id is *44554*.
>
> 2.  one stage of the previous batch is *44549*.
>
> 3.  the last task of stage *44554* is finished at: 15/05/21 21:17:36. ,
> the stage was marked as finished @ 15/05/21 21:17:43.
>
> 4. from the driver log we found that the stage *44549* was marked
> finished @ 15/05/21 21:17:43.
>
>
>
> From before and the code we know that:
>
> 1.        the stage marked finished about *7 s* later after the last task
> of the stage finished
>
>
>
> 2.       There is a EventLoop in DAGScheduler which marked the stage
> finished. It is implement by a single demean thread with a
> LinkedBlockingDeque.
>
>
>
> 3.       From the log we found that the stage :*44549* *which * belongs
> to the previous batch was in the queue before the stage 44554.
>
>
>
> 4.       The stage of *44554* cannot be marked finished although all the
> tasks were finished. Because *44549* was before.
>
>
>
> Q:
>
>
>
> 1.       Any suggestion to avoid this bad situation? Tasks finished while
> stage cannot be marked finished as soon as possible
>
> 2.       Does the demean thread suitable here?
>
> 3.       Does multithread to handle the LinkedBlockingDeque will be
> better ?
>
>
>
>
>
> Triones Deng
>
>
>
> Thanks
>
>
>
>
>
> *Stage Info:*
>
>
>
>
>
> Driver log:
>
>
>
>
>
> *15/05/21 21:17:36 INFO
> [org.apache.spark.scheduler.TaskSetManager---task-result-getter-3]:
> Finished task 180.0 in stage 44554.0 *(TID 1291943) in 3512 ms on
> gd6-mercury-spark-010.idc.vip.com (191/191)
>
> 15/05/21 21:17:36 INFO
> [org.apache.spark.scheduler.TaskSchedulerImpl---task-result-getter-3]:
> Removed TaskSet 44554.0, whose tasks have all completed, from pool default
>
>
>
> ........
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.scheduler.DAGScheduler---sparkDriver-akka.actor.default-dispatcher-44]:
> Parents of final stage: List(Stage 44579)
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.scheduler.DAGScheduler---sparkDriver-akka.actor.default-dispatcher-44]:
> Missing parents: List(Stage 44579)
>
> *15/05/21 21:17:43 INFO
> [org.apache.spark.scheduler.DAGScheduler---sparkDriver-akka.actor.default-dispatcher-44]:
> Stage 44549 (getCallSite at DStream.scala:294) finished in 41.410 s*
>
> 15/05/21 21:17:43 INFO [org.apache.spark.SparkContext---pool-7-thread-19]:
> Job finished: getCallSite at DStream.scala:294, took 103.732781299 s
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.streaming.scheduler.JobScheduler---sparkDriver-akka.actor.default-dispatcher-58]:
> Finished job streaming job 1432214160000 ms.1 from job set of time
> 1432214160000 ms
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.scheduler.DAGScheduler---sparkDriver-akka.actor.default-dispatcher-44]:
> Stage 44547 (getCallSite at DStream.scala:294) finished in 46.843 s
>
> 15/05/21 21:17:43 INFO [org.apache.spark.SparkContext---pool-7-thread-10]:
> Job finished: getCallSite at DStream.scala:294, took 103.733034875 s
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.streaming.scheduler.JobScheduler---sparkDriver-akka.actor.default-dispatcher-58]:
> Finished job streaming job 1432214160000 ms.11 from job set of time
> 1432214160000 ms
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.scheduler.DAGScheduler---sparkDriver-akka.actor.default-dispatcher-44]:
> Stage 44541 (getCallSite at DStream.scala:294) finished in 43.863 s
>
> 15/05/21 21:17:43 INFO [org.apache.spark.SparkContext---pool-7-thread-5]:
> Job finished: getCallSite at DStream.scala:294, took 103.73375696 s
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.scheduler.TaskSetManager---sparkDriver-akka.actor.default-dispatcher-49]:
> Starting task 157.0 in stage 44573.0 (TID 1292019,
> gd6-mercury-spark-014.idc.vip.com, PROCESS_LOC
>
> AL, 1317 bytes)
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.streaming.scheduler.JobScheduler---sparkDriver-akka.actor.default-dispatcher-15]:
> Finished job streaming job 1432214160000 ms.12 from job set of time
> 1432214160000 ms
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.streaming.scheduler.JobScheduler---sparkDriver-akka.actor.default-dispatcher-15]:
> Total delay: 103.757 s for time 1432214160000 ms (execution: 103.740 s)
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.rdd.MappedValuesRDD---sparkDriver-akka.actor.default-dispatcher-37]:
> Removing RDD 110447 from persistence list
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.scheduler.TaskSetManager---sparkDriver-akka.actor.default-dispatcher-49]:
> Starting task 144.0 in stage 44573.0 (TID 1292020,
> gd6-mercury-spark-011.idc.vip.com, PROCESS_LOC
>
> AL, 1317 bytes)
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.scheduler.TaskSetManager---task-result-getter-0]:
> Finished task 0.0 in stage 44573.0 (TID 1291947) in 16 ms on
> gd6-mercury-spark-014.idc.vip.com (1/191)
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.scheduler.TaskSetManager---task-result-getter-1]:
> Finished task 119.0 in stage 44573.0 (TID 1292012) in 15 ms on
> gd6-mercury-spark-011.idc.vip.com (2/191)
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.scheduler.TaskSetManager---sparkDriver-akka.actor.default-dispatcher-49]:
> Starting task 145.0 in stage 44573.0 (TID 1292021,
> gd6-mercury-spark-011.idc.vip.com, PROCESS_LOC
>
> AL, 1317 bytes)
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.scheduler.TaskSetManager---task-result-getter-2]:
> Finished task 143.0 in stage 44573.0 (TID 1292016) in 16 ms on
> gd6-mercury-spark-011.idc.vip.com (3/191)
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.storage.BlockManager---sparkDriver-akka.actor.default-dispatcher-69]:
> Removing RDD 110447
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.rdd.ShuffledRDD---sparkDriver-akka.actor.default-dispatcher-37]:
> Removing RDD 110446 from persistence list
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.storage.BlockManager---sparkDriver-akka.actor.default-dispatcher-61]:
> Removing RDD 110446
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.rdd.MappedRDD---sparkDriver-akka.actor.default-dispatcher-37]:
> Removing RDD 110445 from persistence list
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.storage.BlockManager---sparkDriver-akka.actor.default-dispatcher-51]:
> Removing RDD 110445
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.rdd.FilteredRDD---sparkDriver-akka.actor.default-dispatcher-37]:
> Removing RDD 110444 from persistence list
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.storage.BlockManager---sparkDriver-akka.actor.default-dispatcher-69]:
> Removing RDD 110444
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.rdd.MappedRDD---sparkDriver-akka.actor.default-dispatcher-37]:
> Removing RDD 110443 from persistence list
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.storage.BlockManager---sparkDriver-akka.actor.default-dispatcher-71]:
> Removing RDD 110443
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.rdd.ShuffledRDD---sparkDriver-akka.actor.default-dispatcher-37]:
> Removing RDD 110442 from persistence list
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.storage.BlockManager---sparkDriver-akka.actor.default-dispatcher-49]:
> Removing RDD 110442
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.rdd.MappedRDD---sparkDriver-akka.actor.default-dispatcher-37]:
> Removing RDD 110441 from persistence list
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.storage.BlockManager---sparkDriver-akka.actor.default-dispatcher-36]:
> Removing RDD 110441
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.rdd.MappedRDD---sparkDriver-akka.actor.default-dispatcher-37]:
> Removing RDD 110440 from persistence list
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.storage.BlockManager---sparkDriver-akka.actor.default-dispatcher-65]:
> Removing RDD 110440
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.rdd.FilteredRDD---sparkDriver-akka.actor.default-dispatcher-37]:
> Removing RDD 110439 from persistence list
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.storage.BlockManager---sparkDriver-akka.actor.default-dispatcher-36]:
> Removing RDD 110439
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.rdd.FilteredRDD---sparkDriver-akka.actor.default-dispatcher-37]:
> Removing RDD 110438 from persistence list
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.storage.BlockManager---sparkDriver-akka.actor.default-dispatcher-52]:
> Removing RDD 110438
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.rdd.FlatMappedRDD---sparkDriver-akka.actor.default-dispatcher-37]:
> Removing RDD 110437 from persistence list
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.storage.BlockManager---sparkDriver-akka.actor.default-dispatcher-63]:
> Removing RDD 110437
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.rdd.UnionRDD---sparkDriver-akka.actor.default-dispatcher-37]:
> Removing RDD 110436 from persistence list
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.storage.BlockManager---sparkDriver-akka.actor.default-dispatcher-36]:
> Removing RDD 110436
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.rdd.UnionRDD---sparkDriver-akka.actor.default-dispatcher-37]:
> Removing RDD 110421 from persistence list
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.storage.BlockManager---sparkDriver-akka.actor.default-dispatcher-33]:
> Removing RDD 110421
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.rdd.BlockRDD---sparkDriver-akka.actor.default-dispatcher-37]:
> Removing RDD 110286 from persistence list
>
> *15/05/21 21:17:43 INFO
> [org.apache.spark.scheduler.DAGScheduler---sparkDriver-akka.actor.default-dispatcher-44]:
> Stage 44554 (mapToPair at TraceCalculator.java:88) finished in 14.582 s*
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.scheduler.DAGScheduler---sparkDriver-akka.actor.default-dispatcher-44]:
> looking for newly runnable stages
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.scheduler.DAGScheduler---sparkDriver-akka.actor.default-dispatcher-44]:
> running: Set(Stage 44573, Stage 2)
>
>
>
>
>
>
>
>
>
>
>
> *发件人:* 邓刚[技术中心]
> *发送时间:* 2015年5月22日 10:32
> *收件人:* dev@spark.apache.org; user
> *主题:* task all finished, while the stage marked finish long time later
> problem
>
>
>
> Hi all,
>
>
>
>          We are running spark streaming with version 1.1.1. recently we
> found an odd problem.
>
>
>
>          In stage 44554, All the task finished, but the stage marked
> finished long time later, as you can see the log below, the last task
> finished @15/05/21 21:17:36
>
>          And also the stage remove from taskset. But for about 7s later
> @15/05/21 21:17:43. It is finished at DAGScheduler. So all the dependency
> stages of 44554 launched after 15/05/21 21:17:43. (see image later),I
> know there is a config : spark.akka.threads, the default is 4, we do not
> change it. Does this config affect ?
>
>
>
>          Anyone know have any idea about this?
>
>
>
>
>
>
>
>
>
> Drive Log：
>
>
>
> 15/05/21 21:17:36 INFO
> [org.apache.spark.scheduler.TaskSetManager---task-result-getter-3]:
> Finished task 180.0 in stage 44554.0 (TID 1291943) in 3512 ms on
> gd6-mercury-spark-010.idc.vip.com (191/191)
>
> 15/05/21 21:17:36 INFO
> [org.apache.spark.scheduler.TaskSchedulerImpl---task-result-getter-3]:
> Removed TaskSet 44554.0, whose tasks have all completed, from pool default
>
> 15/05/21 21:17:43 INFO
> [org.apache.spark.scheduler.DAGScheduler---sparkDriver-akka.actor.default-dispatcher-44]:
> Stage 44554 (mapToPair at TraceCalculator.java:88) finished in 14.582 s
>
>
>
>
>
> Stage image:
>
>
> 本电子邮件可能为保密文件。如果阁下非电子邮件所指定之收件人，谨请立即通知本人。敬请阁下不要使用、保存、复印、打印、散布本电子邮件及其内容，或将其用于其他任何目的或向任何人披露。谢谢您的合作！
> This communication is intended only for the addressee(s) and may contain
> information that is privileged and confidential. You are hereby notified
> that, if you are not an intended recipient listed above, or an authorized
> employee or agent of an addressee of this communication responsible for
> delivering e-mail messages to an intended recipient, any dissemination,
> distribution or reproduction of this communication (including any
> attachments hereto) is strictly prohibited. If you have received this
> communication in error, please notify us immediately by a reply e-mail
> addressed to the sender and permanently delete the original e-mail
> communication and any attachments from all storage devices without making
> or otherwise retaining a copy.
>