[SPARK-7058] Include RDD deserialization time in "task deserialization time" metric

[JoshRosen]

The web UI's "task deserialization time" metric is slightly misleading because it does not capture the time taken to deserialize the broadcasted RDD.

[JoshRosen]

/cc @kayousterhout @rxin.

I noticed this in some benchmarking work that I'm doing (more details on the JIRA: https://issues.apache.org/jira/browse/SPARK-7058). Before this patch, we would almost always report 1 or 2 millisecond deserialization times. Now that this metric captures all of the deserialization costs, I'm seeing tasks that spend between 70 and 150ms in deserialization.

I have several ideas of how to optimize this deserialization to reduce this time and I'll address them later patches.

[JoshRosen]

As written here, I guess that this double-counts some of the time spent in execution, so I probably need to move the setting of the task start time into Task. Let me make that change now.

[kayousterhout]

Why this change? Aren't these two things equivalent?

[JoshRosen]

Yep, it's not necessary; will roll back to minimize diff.

[kayousterhout]

Thanks for fixing this @JoshRosen! I've sometimes wondered if it would be helpful to specifically break out the broadcast time to help folks with debugging? In any case, this is a fine intermediate solution, even if we do decide to break out broadcast time eventually.

[JoshRosen]

I've updated this patch to push the calculation of the task run time into the Task itself; this avoids double-counting of the deserialization time, which was breaking the calculation of scheduler delay.

[kayousterhout]

It makes me a little nervous that there's now a time gap between deserializeEndTime and when taskStartTime gets calculated. This should be very small (there's just the intermediate call to updateEpoch) but sometimes things like this get bigger over time (as code changes etc.), and that will make the metrics very confusing. Can the task class expose executorDeserializeTime, and then Executor.scala can call that at the end to appropriately set all of the metrics? I also slightly prefer that approach because it consolidates the metric setting to be mostly in Executor.scala.

[kayousterhout]

Also it is prohibitively difficult to write a unit test for this? I suspect the answer is yes...

[JoshRosen]

I think that the right way to unit test this would be to get the time via the Clock interface instead of calling System.currentTimeMillis() directly, create a static Clock instance somewhere, then rig objects to advance the time on this clock instance at various points, such as deserialization, task execution, etc. This is totally doable, but it might involve a lot of changes to properly pass the Clock instance to the right places.

[JoshRosen]

Exposing the time from Task seems like a better design; I've updated to incorporate this idea.

[SparkQA]

Test build #30771 has finished for PR 5635 at commit 1752f0e.

• This patch passes all tests.
• This patch merges cleanly.
• This patch adds no public classes.
• This patch does not change any dependencies.

[SparkQA]

Test build #30777 has finished for PR 5635 at commit 21f5b47.

• This patch passes all tests.
• This patch merges cleanly.
• This patch adds no public classes.
• This patch does not change any dependencies.

[SparkQA]

Test build #30782 has finished for PR 5635 at commit 4f52910.

• This patch passes all tests.
• This patch merges cleanly.
• This patch adds no public classes.
• This patch does not change any dependencies.

[kayousterhout]

Nit: It would be super helpful to have a comment here to say something to describe the two components of this, like "Deserialization happens in two parts: first, we deserialize a Task object, which includes the Partition. Second, Task.run() deserializes the RDD and function to be run."

[kayousterhout]

One more nit: could you update the task deserialization time tooltip to explicitly say that it includes the time to read the broadcasted task?

Other than that and the other two small comments I had, LGTM!

[kayousterhout]

LGTM!

[SparkQA]

Test build #30866 has finished for PR 5635 at commit ed90f75.

• This patch passes all tests.
• This patch merges cleanly.
• This patch adds no public classes.
• This patch does not change any dependencies.

[rxin]

LGTM!