[SPARK-29003][CORE] Add `start` method to ApplicationHistoryProvider to avoid deadlock on startup by shanyu · Pull Request #25705 · apache/spark

shanyu · 2019-09-06T00:53:08Z

What changes were proposed in this pull request?

During Spark History Server startup, there are two things happening simultaneously that call into java.nio.file.FileSystems.getDefault() and we sometime hit JDK-8194653.

start jetty server
start ApplicationHistoryProvider (which reads files from HDFS)

We should do these two things sequentially instead of in parallel.
We introduce a start() method in ApplicationHistoryProvider (and its subclass FsHistoryProvider), and we do initialize inside the start() method instead of the constructor.
In HistoryServer, we explicitly call provider.start() after we call bind() which starts the Jetty server.

Why are the changes needed?

It is a bug that occasionally starting Spark History Server results in process hang due to deadlock among threads.

Does this PR introduce any user-facing change?

No.

How was this patch tested?

I stress tested this PR with a bash script to stop and start Spark History Server more than 1000 times, it worked fine. Previously I can only do the stop/start loop less than 10 times before I hit the deadlock issue.

merge from apache master

Signed-off-by: Shanyu Zhao <shzhao@microsoft.com>

HeartSaVioR

The approach looks OK to me, though I'd call provider.start() to different place - commented.

Left some comments. There's some simpler workaround (like pre-calling FileSystem.getDefault() in main method of HistoryServer) so reviewer can weigh which approach makes more sense.

Before that, could you change the title of PR to respect the format, like below?

[SPARK-29003][CORE] Fix deadlock in startup of Spark History Server

Most of titles in Spark PRs are explaining what the patch is addressing, not the symptom of the issue.

HeartSaVioR · 2019-09-06T02:49:53Z

core/src/main/scala/org/apache/spark/deploy/history/FsHistoryProvider.scala

  }

-  val initThread = initialize()
+  var initThread:Thread = null


nit: space between : and Thread.

HeartSaVioR · 2019-09-06T02:53:06Z

core/src/main/scala/org/apache/spark/deploy/history/HistoryServer.scala

  /** Bind to the HTTP server behind this web interface. */
  override def bind() {
    super.bind()
+    provider.start()


I'd rather place provider.start() before or after server.bind() in main(), not here. It feels really odd to start provider when calling bind.

That makes sense. Done.

felixcheung · 2019-09-06T03:41:52Z

what he says ^^

HeartSaVioR · 2019-09-06T20:42:36Z

As I commented in JIRA issue, it seems to be a known issue in JDK 8, though the fixed version is too high (8u231) which Spark cannot always expect on this. So good to have workaround.

dongjoon-hyun · 2019-09-07T01:17:04Z

ok to test

SparkQA · 2019-09-07T01:20:04Z

Test build #110274 has finished for PR 25705 at commit c27e35e.

This patch fails Scala style tests.
This patch merges cleanly.
This patch adds no public classes.

dongjoon-hyun · 2019-09-07T01:22:53Z

Hi, @shanyu .

There is a Scala style issue. Could you run dev/scalastyle in your PR directory and fix?

Scalastyle checks failed at following occurrences:
[error] /home/jenkins/workspace/SparkPullRequestBuilder/core/src/main/scala/org/apache/spark/deploy/history/FsHistoryProvider.scala:203:16: No space after token :

Also, please don't forget the above comments from @HeartSaVioR and @felixcheung .

shanyu · 2019-09-10T00:22:26Z

Will do. Thanks.

Sorry for the delay, for some reason, I don't get email update when my PR is reviewed and comments left here...

Signed-off-by: Shanyu Zhao <shzhao@microsoft.com>

shanyu · 2019-09-10T00:37:29Z

Addressed all feedback. Regarding to the point of simpler workaround raised by @HeartSaVioR, I feel that adding start() to provider seems more appropriate. There should be a way to control when to start provider as it is odd today that there is a stop() but not a start() method for provider. And calling FileSystems.getDefault() in main function seems strange and hacky.

HeartSaVioR · 2019-09-10T01:01:45Z

core/src/main/scala/org/apache/spark/deploy/history/FsHistoryProvider.scala

  }

-  val initThread = initialize()
+  var initThread : Thread = null


sorry nit again: no space between d and :. Please refer replayExecutor for how to space.

HeartSaVioR

LGTM except nit.

Signed-off-by: Shanyu Zhao <shzhao@microsoft.com>

SparkQA · 2019-09-10T02:25:42Z

Test build #110381 has finished for PR 25705 at commit 6fcf84c.

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

HeartSaVioR

Ah I forgot the test suites - test failures look relevant.

There's FsHistoryProvider in HistoryServerSuite and we haven't modify the test to call start().
Could you fix the case, as well as search all cases initializing ApplicationHistoryProvider and its descendant to call start() properly?

SparkQA · 2019-09-10T04:13:20Z

Test build #110386 has finished for PR 25705 at commit c3b4411.

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

Signed-off-by: Shanyu Zhao <shzhao@microsoft.com>

HeartSaVioR · 2019-09-10T07:00:43Z

Hmm... you may need to search and fix manually instead of just fixing the case in failed suite. (Or maybe you may need to run tests in your dev. environment at least for core module.)

I can easily find more spots to fix. Mostly you may need to call start() wherever instances of descendants of ApplicationHistoryProvider class are initialized.

SparkQA · 2019-09-10T07:05:02Z

Test build #110398 has finished for PR 25705 at commit 046dd76.

This patch fails due to an unknown error code, -9.
This patch merges cleanly.
This patch adds no public classes.

shanyu · 2019-09-10T19:30:44Z

I searched the code base and I didn't see other descendants of ApplicationHistoryProvider. The latest build passed all tests in "org.apache.spark.deploy.history", but it says "fails due to an unknown error code, -9", I have no idea what this means. Could it be an infra issue?

HeartSaVioR · 2019-09-10T23:45:44Z

You can find all implementations for ApplicationHistoryProvider in IDE, for me, IntelliJ. Other than FsHistoryProvider, they're in test suites.

Seems like you missed to add start() for all places initializing FsHistoryProvider, which means calling startPolling() is missing: for testing, background threads will not be launched so that's OK, but initializing disk manager and validating log directory are missing. Test suites don't concern about it so test passes (I'd say it's luck), but given it's unintentional to not add start(), we would be better to fix that.

HeartSaVioR · 2019-09-11T00:38:30Z

Just submitted a PR shanyu#2 which addresses missing spots.

HeartSaVioR · 2019-09-11T01:08:56Z

it says "fails due to an unknown error code, -9", I have no idea what this means. Could it be an infra issue?

That might be intermittent failure and we can run the build again. If you merge my PR and push to the branch the build will rerun, so no worries.

shanyu · 2019-09-11T02:10:07Z

Thank you @HeartSaVioR!
I have added the provider.start() to HistoryServerSuite, it is in my PR.
I didn't add them to FsHistoryProvider because I see no need to, as you mentioned already. The test suite knows the implementation so it does not have to follow the start/stop pattern. For one thing the tests didn't call stop(). If we are to modify the implementation of FsHistoryProvider.start() we can add start() at that point.

HeartSaVioR · 2019-09-11T02:36:00Z

Hmm... yes I agree it might be weird if we don't follow start/stop pattern. What I'm concerned about is the change would also make tests skip initializing. If the test calls updateAndCheck(), it misses initialization. It doesn't let existing tests be broken, but brings some unintentional side-effect.

I think we even need to call initialize instead if it's weird for us to call start without calling stop, but given tests are passing, let's hear more voice on committers.

HeartSaVioR · 2019-09-11T02:36:52Z

retest this, please

shanyu · 2019-09-11T04:55:13Z

What I'm concerned about is the change would also make tests skip initializing. If the test calls updateAndCheck(), it misses initialization. It doesn't let existing tests be broken, but brings some unintentional side-effect.

Calling updateAndCheck() without start() in FsHistoryProviderSuite is fine because start() just waits for safe mode exit and for this suite of tests it is irrelevant.

SparkQA · 2019-09-11T05:01:22Z

Test build #110452 has finished for PR 25705 at commit 046dd76.

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

HeartSaVioR · 2019-09-11T05:19:53Z

start() just waits for safe mode exit and for this suite of tests it is irrelevant.

No. There're some initializations happening in startPolling(), and it's only called once we call initialize(). Even IS_TESTING is set, remaining initializations are executed.

spark/core/src/main/scala/org/apache/spark/deploy/history/FsHistoryProvider.scala

Lines 243 to 284 in 7f36cd2

    
           private def startPolling(): Unit = { 
        
             diskManager.foreach(_.initialize()) 
        
             // Validate the log directory. 
        
             val path = new Path(logDir) 
        
             try { 
        
               if (!fs.getFileStatus(path).isDirectory) { 
        
                 throw new IllegalArgumentException( 
        
                   "Logging directory specified is not a directory: %s".format(logDir)) 
        
               } 
        
             } catch { 
        
               case f: FileNotFoundException => 
        
                 var msg = s"Log directory specified does not exist: $logDir" 
        
                 if (logDir == DEFAULT_LOG_DIR) { 
        
                   msg += " Did you configure the correct one through spark.history.fs.logDirectory?" 
        
                 } 
        
                 throw new FileNotFoundException(msg).initCause(f) 
        
             } 
        
             // Disable the background thread during tests. 
        
             if (!conf.contains(IS_TESTING)) { 
        
               // A task that periodically checks for event log updates on disk. 
        
               logDebug(s"Scheduling update thread every $UPDATE_INTERVAL_S seconds") 
        
               pool.scheduleWithFixedDelay( 
        
                 getRunner(() => checkForLogs()), 0, UPDATE_INTERVAL_S, TimeUnit.SECONDS) 
        
               if (conf.get(CLEANER_ENABLED)) { 
        
                 // A task that periodically cleans event logs on disk. 
        
                 pool.scheduleWithFixedDelay( 
        
                   getRunner(() => cleanLogs()), 0, CLEAN_INTERVAL_S, TimeUnit.SECONDS) 
        
               } 
        
               if (conf.contains(DRIVER_LOG_DFS_DIR) && conf.get(DRIVER_LOG_CLEANER_ENABLED)) { 
        
                 pool.scheduleWithFixedDelay(getRunner(() => cleanDriverLogs()), 
        
                   0, 
        
                   conf.get(DRIVER_LOG_CLEANER_INTERVAL), 
        
                   TimeUnit.SECONDS) 
        
               } 
        
             } else { 
        
               logDebug("Background update thread disabled for testing") 
        
             } 
        
           }

Safe mode exit is just one of functionalities in initialize(). So while we might be able to say it doesn't break the existing tests so it's kind of safe, it still brings side-effect.

shanyu · 2019-09-11T19:07:11Z

@HeartSaVioR Yeah you are right, it also calls startPolling() after exit from safe mode. That's why we need it in HistoryServerSuite tests. For FsHistoryProviderSuite, we always force update so it should be OK.

HeartSaVioR · 2019-09-11T20:53:52Z

I'm thinking out logically, we're just missing to initialize FsHistoryProvider and its descendants for some of tests, regardless of the fact the initialization doesn't break actual tests. (diskManager.initialize is not a "must" thing to call so tests are passing, but what if it's a "must"?)

It doesn't seem to be logically correct to not initialize just because tests are passing, but that's only me, and remaining code change itself is good so it's not a blocker (maybe minor?) and I'll leave a decision to committers. Let's wait and hear feedbacks.

HeartSaVioR · 2019-09-11T20:54:45Z

cc. @felixcheung @dongjoon-hyun Could you revisit this PR? Thanks in advance!

dongjoon-hyun · 2019-09-12T07:42:52Z

core/src/main/scala/org/apache/spark/deploy/history/ApplicationHistoryProvider.scala

   */
  def stop(): Unit = { }

+  def start(): Unit = { }


nit. Could you add a function description like def stop()?

Done. Thanks!

dongjoon-hyun

+1, LGTM with one nit comment. This is fixed since 8u212 but we had better have this as @HeartSaVioR commented before. Since both classes are private, I think the change will be okay. Thank you, @shanyu and @HeartSaVioR !

cc @vanzin

Signed-off-by: Shanyu Zhao <shzhao@microsoft.com>

SparkQA · 2019-09-12T19:53:39Z

Test build #110525 has finished for PR 25705 at commit e8d8024.

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

dongjoon-hyun · 2019-09-12T21:52:16Z

core/src/main/scala/org/apache/spark/deploy/history/ApplicationHistoryProvider.scala

  def stop(): Unit = { }

+  /**
+   * Called when the server is starting up.


Ur, this seems to be copied blindly~
This is not called. We need to call this, doesn't we?

Could you describe the expected behavior and the expected exceptions of this function, please?

@dongjoon-hyun This is the same as stop() that is called by the server (HistoryServer), start() should be called during server starting up. I'll add a few more sentence to describe that it should do and why we added it.

Signed-off-by: Shanyu Zhao <shzhao@microsoft.com>

SparkQA · 2019-09-14T00:54:42Z

Test build #110576 has finished for PR 25705 at commit 75dc86d.

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

dongjoon-hyun

+1, LGTM again. Thank you, @shanyu and @HeartSaVioR .
Since it's difficult to add a deadlock test case here, this look okay to me.
Merged to master.

…to avoid deadlock on startup ### What changes were proposed in this pull request? During Spark History Server startup, there are two things happening simultaneously that call into `java.nio.file.FileSystems.getDefault()` and we sometime hit [JDK-8194653](https://bugs.openjdk.java.net/browse/JDK-8194653). 1) start jetty server 2) start ApplicationHistoryProvider (which reads files from HDFS) We should do these two things sequentially instead of in parallel. We introduce a start() method in ApplicationHistoryProvider (and its subclass FsHistoryProvider), and we do initialize inside the start() method instead of the constructor. In HistoryServer, we explicitly call provider.start() after we call bind() which starts the Jetty server. ### Why are the changes needed? It is a bug that occasionally starting Spark History Server results in process hang due to deadlock among threads. ### Does this PR introduce any user-facing change? No. ### How was this patch tested? I stress tested this PR with a bash script to stop and start Spark History Server more than 1000 times, it worked fine. Previously I can only do the stop/start loop less than 10 times before I hit the deadlock issue. Closes apache#25705 from shanyu/shanyu-29003. Authored-by: Shanyu Zhao <shzhao@microsoft.com> Signed-off-by: Dongjoon Hyun <dhyun@apple.com>

shanyu added 2 commits September 5, 2019 17:35

Merge pull request #1 from apache/master

624206e

merge from apache master

SPARK-29003: Spark history server startup hang due to deadlock

c27e35e

Signed-off-by: Shanyu Zhao <shzhao@microsoft.com>

HeartSaVioR reviewed Sep 6, 2019

View reviewed changes

dongjoon-hyun added the SPARK CORE label Sep 6, 2019

dongjoon-hyun changed the title ~~SPARK-29003: Spark history server startup hang due to deadlock~~ [SPARK-29003][CORE] Spark history server startup hang due to deadlock Sep 7, 2019

Addressing review feedback

6fcf84c

Signed-off-by: Shanyu Zhao <shzhao@microsoft.com>

shanyu changed the title ~~[SPARK-29003][CORE] Spark history server startup hang due to deadlock~~ [SPARK-29003][CORE] Fix deadlock in startup of Spark History Server Sep 10, 2019

HeartSaVioR reviewed Sep 10, 2019

View reviewed changes

HeartSaVioR approved these changes Sep 10, 2019

View reviewed changes

Addressing feedback

c3b4411

Signed-off-by: Shanyu Zhao <shzhao@microsoft.com>

HeartSaVioR requested changes Sep 10, 2019

View reviewed changes

Fix test failure

046dd76

Signed-off-by: Shanyu Zhao <shzhao@microsoft.com>

This was referenced Sep 11, 2019

Address missing spots in spark#25705 - add start() for all initializations #25750

Closed

Add start() for all missed initialization of descendants of ApplicationHistoryProvider shanyu/spark#2

Closed

dongjoon-hyun reviewed Sep 12, 2019

View reviewed changes

Add comments to start()

e8d8024

Signed-off-by: Shanyu Zhao <shzhao@microsoft.com>

dongjoon-hyun reviewed Sep 12, 2019

View reviewed changes

Update comments for start()

75dc86d

Signed-off-by: Shanyu Zhao <shzhao@microsoft.com>

dongjoon-hyun changed the title ~~[SPARK-29003][CORE] Fix deadlock in startup of Spark History Server~~ [SPARK-29003][CORE] Add start method to ApplicationHistoryProvider to avoid deadlock on startup Sep 14, 2019

dongjoon-hyun approved these changes Sep 14, 2019

View reviewed changes

dongjoon-hyun closed this in 174d910 Sep 14, 2019

Conversation

shanyu commented Sep 6, 2019 • edited by dongjoon-hyun Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

What changes were proposed in this pull request?

Why are the changes needed?

Does this PR introduce any user-facing change?

How was this patch tested?

Uh oh!

HeartSaVioR left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

HeartSaVioR Sep 6, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

felixcheung commented Sep 6, 2019

Uh oh!

HeartSaVioR commented Sep 6, 2019

Uh oh!

dongjoon-hyun commented Sep 7, 2019

Uh oh!

SparkQA commented Sep 7, 2019

Uh oh!

dongjoon-hyun commented Sep 7, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

shanyu commented Sep 10, 2019

Uh oh!

shanyu commented Sep 10, 2019

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

HeartSaVioR left a comment

Choose a reason for hiding this comment

Uh oh!

SparkQA commented Sep 10, 2019

Uh oh!

HeartSaVioR left a comment

Choose a reason for hiding this comment

Uh oh!

SparkQA commented Sep 10, 2019

Uh oh!

HeartSaVioR commented Sep 10, 2019

Uh oh!

SparkQA commented Sep 10, 2019

Uh oh!

shanyu commented Sep 10, 2019

Uh oh!

HeartSaVioR commented Sep 10, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

HeartSaVioR commented Sep 11, 2019

Uh oh!

HeartSaVioR commented Sep 11, 2019

Uh oh!

shanyu commented Sep 11, 2019

Uh oh!

HeartSaVioR commented Sep 11, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

HeartSaVioR commented Sep 11, 2019

Uh oh!

shanyu commented Sep 11, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

SparkQA commented Sep 11, 2019

Uh oh!

HeartSaVioR commented Sep 11, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

shanyu commented Sep 11, 2019

shanyu commented Sep 6, 2019 •

edited by dongjoon-hyun

Loading

HeartSaVioR left a comment •

edited

Loading

HeartSaVioR Sep 6, 2019 •

edited

Loading

dongjoon-hyun commented Sep 7, 2019 •

edited

Loading

HeartSaVioR commented Sep 10, 2019 •

edited

Loading

HeartSaVioR commented Sep 11, 2019 •

edited

Loading

shanyu commented Sep 11, 2019 •

edited

Loading

HeartSaVioR commented Sep 11, 2019 •

edited

Loading

dongjoon-hyun left a comment •

edited

Loading

dongjoon-hyun left a comment •

edited

Loading