[SPARK-21099][Spark Core] INFO Log Message Using Incorrect Executor I…

[ihazem]

…dle Timeout Value

What changes were proposed in this pull request?

Updated the INFO logging method (logInfo) to use $timeout instead, which uses cachedExecutorIdleTimeoutS if the executor has cached blocks

How was this patch tested?

Testing was done by doing the following:

1. Update spark-defaults.conf to set the following:
   executorIdleTimeout=30
   cachedExecutorIdleTimeout=20
2. Update log4j.properties to set the following:
   shell.log.level=INFO
3. Run the following in spark-shell:
   scala> val textFile = sc.textFile("/user/spark/applicationHistory/app_1234")
   scala> textFile.cache().count()
4. After 20 secs I see the timeout message for idle cache, and after 30 secs I see the timeout message for executor (executorIdleTimeoutS).

Please review http://spark.apache.org/contributing.html before opening a pull request.

[jerryshao]

LGTM. BTW can you please complement the PR description, thanks.

[srowen]

Jenkins test this please

[SparkQA]

Test build #78086 has finished for PR 18308 at commit 00a42e7.

• This patch fails to build.
• This patch merges cleanly.
• This patch adds no public classes.

[jerryshao]

This variable executorId is not defined, should change to removedExecutorId.

[jerryshao]

And final semicolon ";" is not necessary.

[jerryshao]

Btw, there could be a chance when querying executor from BlockManager, the executor/block manager was already removed, so we will potentially get false.

[ihazem]

@jerryshao - I pushed another commit fixing removedExecutorId and removing ';'...thx for feedback on that.

Regarding the edge case where the block manager was already removed and could potentially get false. then this:
 val timeout = if (hasCachedBlocks) cachedExecutorIdleTimeoutS else executorIdleTimeoutS
would just evaluate to executorIdleTimeoutS and wouldn't matter anyway since executor is gone. I wonder if whether executor is completely gone or whether executor is still there but has no cached RDD, if both scenarios return false. That seems to be the case (unless I'm reading it wrong) based on HasCachedBlocks in core/src/main/scala/org/apache/spark/storage/BlockManagerMasterEndpoint.scala

[vanzin]

ok to test

[SparkQA]

Test build #78126 has finished for PR 18308 at commit 0f1c467.

• This patch fails Spark unit tests.
• This patch merges cleanly.
• This patch adds no public classes.

[jerryshao]

I wonder if whether executor is completely gone or whether executor is still there but has no cached RDD, if both scenarios return false.

Yes, that's the case, we cannot differentiate this two scenarios. But I think it is fine, since it is just a log issue and hard for us to differentiate them in the current code.

[SparkQA]

Test build #3799 has finished for PR 18308 at commit 0f1c467.

• This patch passes all tests.
• This patch merges cleanly.
• This patch adds no public classes.

[vanzin]

This is a pretty expensive call just so you can print a more accurate log message... at the very least it should be inside the logInfo call:

logInfo {
  expensiveStuff()
  "This is the log message referencing the expensive stuff."
}

But I'd prefer a solution that doesn't make this call at all, since INFO is more often than not enabled.

[AmplabJenkins]

Can one of the admins verify this patch?

[srowen]

Ping @ihazem

[srowen]

Ping @ihazem to update or close

[ihazem]

@srowen - I modified to take @vanzin recommendation of putting the logic in the logInfo call instead. I'm open to hearing any recommendations on using a less expensive call. Thx!

[srowen]

This is hard to read. @vanzin 's idea is better. Can you split this into two statements? cheap one at info, expensive one at debug?

[jiangxb1987]

Can you update the title to:

[SPARK-21099][Core] Log cachedExecutorIdleTimeoutS instead of executorIdleTimeoutS  if the executor has cached blocks

?

[jerryshao]

Is this the final modified code @ihazem , why do you have hasCachedBlocks logics both inside and outside of logInfo statement? Also the code is too long.

Can you please at least do a round of self-review before pushing the changes.

[ihazem]

@jerryshao - sorry about that...let me remove the logic outside the logInfo statements. Missed that. I'll do some more self-review and peer-review going fwd before submitting to not waste everyone's time here.

@jiangxb1987 - i'll update title per your recommendation

@srowen - do you or @vanzin have any recommendations on making a cheaper call in the info level? I can definitely make the more expensive call at debug/warn, but could use some direction on a cheaper call for the info level. Basically, we want to use the cachedExecutorIdleTimeoutS if the executor has cached blocks (whereas right now it uses executorIdleTimeoutS).

Thx!

[vanzin]

There is no cheaper call you can make. Which is the problem here. So either you have to modify the code so that it keeps track of why the executor has timed out (i.e. more state being passed around), or you need to tweak the message so that it says that the timeout is different when there are cached blocks on the executor.

I'm not so sure there's a lot to gain from printing the exact timeout value in this message, so I'm leaning towards just tweaking the message a little bit (e.g. add "or $otherTimeout ms if executor had cached blocks"), or even not doing anything.