[SPARK-32287][TESTS] Flaky Test: ExecutorAllocationManagerSuite.add executors default profile

[tgravescs]

What changes were proposed in this pull request?

I wasn't able to reproduce the failure but the best I can tell is that the allocation manager timer triggers and call doRequest. The timeout is 10s so try to increase that to 30seconds.

Why are the changes needed?

test failure

Does this PR introduce any user-facing change?

no

How was this patch tested?

unit test

[tgravescs]

@Ngone51

[dongjoon-hyun]

So, this is for the same reason with SPARK-22864 at line 1604?

[Ngone51]

@tgravescs It happens again at: https://github.com/apache/spark/pull/29418/checks?check_run_id=975304054

BTW, this change only prevents the automatic invocation of schedule() for the second time but the first time invocation of schedule() always happens because the initialDelay is 0?

spark/core/src/main/scala/org/apache/spark/ExecutorAllocationManager.scala

Line 250 in 8f0fef1

executor.scheduleWithFixedDelay(scheduleTask, 0, intervalMillis, TimeUnit.MILLISECONDS)

[tgravescs]

I'm not seeing. a test report in that run?
Yes but it seemed like the failures we were seeing before we after an interation or two or the test starting, although it did vary. If we can see the logs from it we should be able to see timing and possibly some log messages to tell us if that is the problem.

[Ngone51]

I'm not seeing. a test report in that run?

You need to scroll to the end of Run tests: core, unsafe, kvstore, avro section to see the failed tests.

Yes but it seemed like the failures we were seeing before we after an interation or two or the test starting, although it did vary.

Ok, not aware of that...

If we can see the logs from it we should be able to see timing and possibly some log messages to tell us if that is the problem.

@tgravescs A feasible way to debug it is to open a PR in your own fork repository and adds some println in the source code.

@HyukjinKwon I think we still can not see the complete logs in GithubActions like the unit-test.log in Jenkins. I mean, even we download the archive logs after checks finished.

[HyukjinKwon]

I think I can try to upload that specific log file as an artifact (so we can download) Let me take a look in coming few days.

[Ngone51]

BTW, the unit-tests.log file is generated by log4j:

spark/core/src/test/resources/log4j.properties

Line 23 in b33066f

log4j.appender.file.file=target/unit-tests.log

[tgravescs]

thanks for updating and uploading the logs, let me know if you see a build that has this test failure and I'll look at the log

[dongjoon-hyun]

+1, LGTM since this is test-only configuration and already is supposed to have a really long value since 2.3.0.
Also, GitHub Action is passed. Merged to master/3.0.

[tgravescs]

thanks @dongjoon-hyun if you see this failing again let me know and I'll try to reproduce again. I ran it in a subset of the tests in a loop and wasn't able to reproduce locally.

[dongjoon-hyun]

Sure~ I'll monitor on GitHub Action result. Thanks.

[SparkQA]

Test build #126506 has finished for PR 29225 at commit 3af6ab9.

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

[Ngone51]

Late LGTM. Thank you @tgravescs

[HyukjinKwon]

Thank you @tgravescs for fixing this.

[HyukjinKwon]

I saw this again:

[info] - add executors default profile *** FAILED *** (38 milliseconds)
[info]   4 did not equal 2 (ExecutorAllocationManagerSuite.scala:132)
[info]   org.scalatest.exceptions.TestFailedException:
[info]   at org.scalatest.Assertions.newAssertionFailedException(Assertions.scala:472)
[info]   at org.scalatest.Assertions.newAssertionFailedException$(Assertions.scala:471)
[info]   at org.scalatest.Assertions$.newAssertionFailedException(Assertions.scala:1231)
[info]   at org.scalatest.Assertions$AssertionsHelper.macroAssert(Assertions.scala:1295)
[info]   at org.apache.spark.ExecutorAllocationManagerSuite.$anonfun$new$7(ExecutorAllocationManagerSuite.scala:132)
[info]   at org.scalatest.OutcomeOf.outcomeOf(OutcomeOf.scala:85)
[info]   at org.scalatest.OutcomeOf.outcomeOf$(OutcomeOf.scala:83)
[info]   at org.scalatest.OutcomeOf$.outcomeOf(OutcomeOf.scala:104)
[info]   at org.scalatest.Transformer.apply(Transformer.scala:22)
[info]   at org.scalatest.Transformer.apply(Transformer.scala:20)
[info]   at org.scalatest.funsuite.AnyFunSuiteLike$$anon$1.apply(AnyFunSuiteLike.scala:189)
[info]   at org.apache.spark.SparkFunSuite.withFixture(SparkFunSuite.scala:158)
[info]   at org.scalatest.funsuite.AnyFunSuiteLike.invokeWithFixture$1(AnyFunSuiteLike.scala:187)
[info]   at org.scalatest.funsuite.AnyFunSuiteLike.$anonfun$runTest$1(AnyFunSuiteLike.scala:199)
[info]   at org.scalatest.SuperEngine.runTestImpl(Engine.scala:306)

with:

[info] - add executors capped by num pending tasks *** FAILED *** (77 milliseconds)
[info]   6 did not equal 5 (ExecutorAllocationManagerSuite.scala:428)
[info]   org.scalatest.exceptions.TestFailedException:
[info]   at org.scalatest.Assertions.newAssertionFailedException(Assertions.scala:472)
[info]   at org.scalatest.Assertions.newAssertionFailedException$(Assertions.scala:471)
[info]   at org.scalatest.Assertions$.newAssertionFailedException(Assertions.scala:1231)
[info]   at org.scalatest.Assertions$AssertionsHelper.macroAssert(Assertions.scala:1295)
[info]   at org.apache.spark.ExecutorAllocationManagerSuite.$anonfun$new$18(ExecutorAllocationManagerSuite.scala:428)
[info]   at org.scalatest.OutcomeOf.outcomeOf(OutcomeOf.scala:85)
[info]   at org.scalatest.OutcomeOf.outcomeOf$(OutcomeOf.scala:83)
[info]   at org.scalatest.OutcomeOf$.outcomeOf(OutcomeOf.scala:104)
[info]   at org.scalatest.Transformer.apply(Transformer.scala:22)
[info]   at org.scalatest.Transformer.apply(Transformer.scala:20)
[info]   at org.scalatest.funsuite.AnyFunSuiteLike$$anon$1.apply(AnyFunSuiteLike.scala:189)
[info]   at org.apache.spark.SparkFunSuite.withFixture(SparkFunSuite.scala:158)
[info]   at org.scalatest.funsuite.AnyFunSuiteLike.invokeWithFixture$1(AnyFunSuiteLike.scala:187)
[info]   at org.scalatest.funsuite.AnyFunSuiteLike.$anonfun$runTest$1(AnyFunSuiteLike.scala:199)
[info]   at org.scalatest.SuperEngine.runTestImpl(Engine.scala:306)
[info]   at org.scalatest.funsuite.AnyFunSuiteLike.runTest(AnyFunSuiteLike.scala:199)

at https://github.com/apache/spark/pull/29278/checks?check_run_id=930261611. I am retriggering.

I will monitor a bit more and update here. If the flakiness is very rare, it would be fine for now.

[tgravescs]

is there anyway to access the unit test detailed logs from GitHub action?

[tgravescs]

It would be really nice if we could get some timestamps on how long tests were taking

[HyukjinKwon]

Oh it shows the timstamps when you download the log. I'll share the timestamps too later when I happene to see this again.

[tgravescs]

so @Ngone51 found this again here:

for the flaky ExecutorAllocationManagerSuite : https://github.com/apache/spark/pull/29452/checks?check_run_id=1008962797

entire test suite ran in less then 5 seconds

The logs that I see are fine up til it fails but the output is intermixed with other test Suites running so its hard to differentiate some of the logs. The only path I see this can changed would be on a decrement triggered by an updateAndSync and the only way it should hit that is if the timer fired. So it might be the initial timer as stated above. I'll put up a PR with some more debugging enabled to see if I can verify it.

[HyukjinKwon]

Thank you @tgravescs a lot for taking a look for this.