I observe massive differences in performance when running individual spec in IDE vs the same spec ru...

# kotest

[wasyl]

I observe massive differences in performance when running individual spec in IDE vs the same spec running as part of entire module tests in console. For example one test in console reports as having taken 5 seconds, whereas that same test in IDE takes 165ms. Another test takes over 20 seconds (!) in console and under a second in IDE. Are there any known inefficiencies here? I’m using instance-per-leaf mode.

[wasyl]

The measurement aren’t very scientific, but I do also notice that tests executed counter in console is basically slowing down as the tests are executing. I’m using Kotest 4.2.3. Initially I can see counter increase at 100 tests per 5 seconds, later on is 1 test per second or so

[wasyl]

And it seems that when running all tests in the module in IDE it takes several seconds, while in console it’s couple of minutes 😕 Reported number of tests doesn’t match but I think it’s just IDE counting them differently than Gradle

[sam]

Can you clarify what you mean by running in the console.

[sam]

do you mean ./gradlew check in a terminal ?

[wasyl]

Yep, ./gradlew someProject:test

[wasyl]

I’m not sure if related but I started profiling the tests to see what’s the issue

[wasyl]

The longest single test takes 1 minut when running directly from Gradle, and spends vast majority of time in testFinished listener, figuring out failures:

[wasyl]

This is just one block but it’s ~20s in several describe blocks side by side

[wasyl]

I think perhaps I’m using very long descriptions (bigDataClass.toString() because now with forAll we still need to differentiate nested nested tests and it’s the easiest way)

[wasyl]

But there’s still something off with running many tests from Gradle. I tried optimizing test names to be shorter and the same test now finishes in 15 seconds when running only that test in Gradle (./gradle someModule:test --tests "that.test.class") but still takes 30 seconds when running all tests in module (before optimizing it took 60 seconds, so still a win)

[wasyl]

Basically seems like isAnscestorOf is a massive hot stop and it’s relatively inefficient under some circumstances. In my case I suspect it’s just deeply nested tests + instance-per-leaf mode + somewhat long descriptions. All in findChildFailure()

[wasyl]

If JUnitTestEngineListener is the same for all tests in Gradle run, it’d also explain the continuous drop in performance, as from what I see all results are appended to a single mutable list, and after each test all the results are filtered again

[wasyl]

Seems like caching Description#id() is a pretty low-hanging fruit?

[wasyl]

Aaaand now I see https://github.com/kotest/kotest/commit/2d3c18399eee285c7140067ba764564b75c6c4c3#diff-f968fee07b934a6aa5511c869f0f5e25 😄

[wasyl]

Aaaand with 4.2.4 we’re down with tests execution time from 5 minutes to one 🎉

[sam]

Perfect :)

[wasyl]

There’s still massive difference on CI though 😛 1 minute locally vs 10 minutes on CI. But that might be Jacoco, or memory pressure, so I’ll investigate it separately

[sam]

Hmmm ok

[sam]

Is locally using gradle as well

[sam]

Or plugin only

[wasyl]

For now I just see that Description#id is created 200k times over the course of tests run, even though at the end there’s only 411 live instances of it, so perhaps the caching might still make sense

[wasyl]

Locally is Gradle as well, overall IDE was always fast so I’m not focusing on it at all

[sam]

Agreed

[sam]

Ok so could be jacoco

[sam]

It does do jvm agent stuff

[sam]

If you can turn it off for a single ci run to see

[wasyl]

Yep I’ll check. Btw this is memory profiling results for my run

[sam]

I will optimise that

[sam]

What tool do you use to get that info

[wasyl]

VisualVm https://visualvm.github.io/

[wasyl]

I installed startup profiler and manually modify jvmargs for the test task such that it attaches and samples from the start

[sam]

Ok cool thanks

[wasyl]

For some tests using forall blocks I seem to also lose a bit of time in isOnPath btw

[wasyl]

That’s again id calculation though, but it seems that the regex patter is created every time?

[wasyl]

the compile is quite heavy so I suppose it could be cached as well

[wasyl]

I also see quite some time in Regex.replace in the id() calculation, but I don’t see how to optimise it 🤔

[sam]

I can't duplicated your profile results, but don't have a lot of heavy nesting. I've made a change so that Description.id is now a val rather than a function, and the regex is now static. That's building as 4.3.0.659-SNAPSHOT if you want to try the snapshot. If it fixes your issue, then I will roll the commit into 4.2.5.

[wasyl]

👍 thanks 🙂 Will try, I see 659 is not up yet though (and there are some failed CI runs for the two related commits fyi)

[sam]

Yeah sorry about that. I've fixed it and will kick off another run shortly.

[sam]

4.3.0.664-SNAPSHOT

[wasyl]

Thank you 🙂 Not very scientific as I don’t have numbers, but I do see a reasonable improvement with the snapshot

[wasyl]

About 6-8 seconds less on the heaviest test. I’ll try to reproduce it in a sample project, I’m pretty sure there’s still some areas it could be optimised (either on my side or Kotest side). It’s quite interesting in that it generates ~700 “tests” (as reported by Gradle), which is a lot for a single class (~400loc)

[wasyl]

It seems like the slowest piece right now is sourceRef() call. I’ll try to get some more information about the specifics though, but I suspect it’s something about the stacktrace being massive 😉

[wasyl]

Yep, the slowest piece now is Throwable.getStackTrace() -> getOurStackTrace() -> getStackTraceElement, which happens for every test. If the SourceRef data is not needed always, perhaps the stacktrace could be retrieved lazily — creating Throwable() is relatively cheap so it could be stored, and stacktrace could be only calculated when needed

[wasyl]

And I think it’s nothing related to nesting really, as the following test:

class Sample: DescribeSpec() {
  describe("root") {
    it("1") { println("Done") }
    it("2") { println("Done") }
    it("3") { println("Done") }
    ...
    it("300") { println("Done") }
  }
}

runs pretty long as well, and spends most of the time in sourceRef(). Why I experience this is just because we have 4 nested forall blocks, and couple assertions on each step, and it adds up to roughly 200-300 assertions. It’s still not that much for a unit test which uses forAll or generators though

[sam]

sourceref might be able to be lazy, I will test that

[reevn]

Appreciate all the effort in here! I've also been seeing the same performance discrepancy between IDE vs Gradle where some bigger files run through very fast with the plugin but very slow in the console

[sam]

Had a play with source ref but it has to stay as it's needed for both the junit integration and the intellij plugin.

[sam]

I've released 4.2.5 with the other perf enhancements though

[wasyl]

Perhaps on JDK 9+ StackWalker could be used? Anyway if it’s a significant bottleneck for someone, one workaround is to use -XX:MaxJavaStackTraceDepth=10 (10 seems to work with current Kotest), assuming there’s no need for full stacktraces elsewhere. This seems to speed up the tests for which the sourceRef is costly (as its performance degrades with the tests depth, it might not be an issue for everyone. I observe noticeable impact with ~400 levels deep stacks, and it seems like using forall results in a bit deeper stacktraces?).
Thanks for looking into it, Sam!

[sam]

Let me see if StackWalker is any faster. If it is, I could use some reflection magic to see if it's on the classpath, and if it is, use it

[wasyl]

I wanted to check it myself, but IntelliJ refused to cooperate when I wanted to change the java sdk to 9 to have those classes in IDE 😕

[sam]

I can test it locally as I'm in jdk11

[sam]

Seems to be 4x faster on short stacks

[sam]

If you want to try snapshot 4.3.0.678-SNAPSHOT and then add a module kotest-framework-jdk9 to your build, that should trigger the usage of stack walker. Would be interesting to see how much quicker it is for you.

[wasyl]

It’s interesting, I don’t see any speedup at all 🤔

[wasyl]

But also the tests don’t fail even if I run them with Java 8, which seems off. I’m definitely adding the jdk9 dependency though

[sam]

So if you add jdk9 dep (and you're on jdk9 of course!) then it should detect the stack walker and use it

[sam]

Otherwise it will silently fall back to thread.stacktrace

[wasyl]

I verified that indeed stack walker is used, but unfortunately the tests take exactly the same amount of time 😕 sorry

[wasyl]

That’s on jdk 11

[sam]

hmmm ok, that's a shame. I have a test that does 100,000 source refs and the time dropped from 2500 to 700

[wasyl]

Yep I saw that one, also on my machine (jdk8) it ran for about 6.5 seconds, which is also interesting.

[sam]

I guess I could add an option to turn it off. Looking at the code again, it's used by the junit listener, but I don't know if it actually does anything

[sam]

It's main use is in the intellij plugin so the test results can link back to the test file

[wasyl]

Perhaps it’d make difference in a test with less refs but with bigger callstacks? Maybe it’s reflection overhead that’s negating some benefits from StackWalker?

[sam]

yes possible

[wasyl]

Anyway, for me the current performance is already good, thanks for all the improvements 🙂 For CI I’ll consider running with smaller max stacktrace depth, and maybe it’ll turn out I configured StackWalker wrong, or that it has some benefits on the CI. For my entire tests suite, on average, sourceRef is no longer the bottleneck, and for individual tests its performance doesn’t matter

[sam]

If you wait for build 4.3.0.679-SNAPSHOT and then try setting the system property

kotest.framework.sourceref.disable=true

[wasyl]

I’ll check that 🙂

[sam]

You can do this inside your gradle file, so that it won't affect running via the plugin

tasks.named<Test>("test") {
   useJUnitPlatform()
   systemProperty("kotest.framework.sourceref.disable", "true")
}

[sam]

If that doesn't help then yes, we'll give up 😂

[wasyl]

With this property set, the tests are ~30% faster 🙂

[sam]

niceeeee