I observe massive differences in performance when running in

Question

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 · Answer

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 · Answer

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 confused Reported number of tests doesn t match but I think it s just IDE counting them differently than Gradle

sam · Answer

Can you clarify what you mean by running in the console

sam · Answer

do you mean gradlew check in a terminal

wasyl · Answer

Yep ` gradlew someProject test`

wasyl · Answer

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

wasyl · Answer

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 · Answer

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

wasyl · Answer

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 · Answer

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 · Answer

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 · Answer

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 · Answer

Seems like caching `Description id ` is a pretty low hanging fruit

wasyl · Answer

Aaaand now I see <https github com kotest kotest commit 2d3c18399eee285c7140067ba764564b75c6c4c3 diff f968fee07b934a6aa5511c869f0f5e25> smile

wasyl · Answer

Aaaand with 4 2 4 we re down with tests execution time from 5 minutes to one tada

sam · Answer

Perfect

wasyl · Answer

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

sam · Answer

Hmmm ok

sam · Answer

Is locally using gradle as well

sam · Answer

Or plugin only

wasyl · Answer

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 · Answer

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

sam · Answer

Agreed

sam · Answer

Ok so could be jacoco

sam · Answer

It does do jvm agent stuff

sam · Answer

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

wasyl · Answer

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

sam · Answer

I will optimise that

sam · Answer

What tool do you use to get that info

wasyl · Answer

VisualVm <https visualvm github io >

wasyl · Answer

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

sam · Answer

Ok cool thanks

wasyl · Answer

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

wasyl · Answer

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

wasyl · Answer

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

wasyl · Answer

I also see quite some time in `Regex replace` in the `id ` calculation but I don t see how to optimise it thinking face

sam · Answer

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 · Answer

+1 thanks slightly smiling face Will try I see 659 is not up yet though and there are some failed CI runs for the two related commits fyi

sam · Answer

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

sam · Answer

4 3 0 664 SNAPSHOT

wasyl · Answer

Thank you slightly smiling face Not very scientific as I don t have numbers but I do see a reasonable improvement with the snapshot

wasyl · Answer

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 · Answer

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 wink

wasyl · Answer

Yep the slowest piece now is `Throwable getStackTrace gt getOurStackTrace gt 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 · Answer

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 · Answer

sourceref might be able to be lazy I will test that

reevn · Answer

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 · Answer

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 · Answer

I ve released 4 2 5 with the other perf enhancements though

wasyl · Answer

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 · Answer

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 · Answer

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 confused

sam · Answer

I can test it locally as I m in jdk11

sam · Answer

Seems to be 4x faster on short stacks

sam · Answer

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 · Answer

It s interesting I don t see any speedup at all thinking face

wasyl · Answer

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 · Answer

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

sam · Answer

Otherwise it will silently fall back to thread stacktrace

wasyl · Answer

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

wasyl · Answer

That s on jdk 11

sam · Answer

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 · Answer

Yep I saw that one also on my machine jdk8 it ran for about 6 5 seconds which is also interesting

sam · Answer

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 · Answer

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

wasyl · Answer

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 · Answer

yes possible

wasyl · Answer

Anyway for me the current performance is already good thanks for all the improvements slightly smiling face 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 · Answer

If you wait for build `4 3 0 679 SNAPSHOT` and then try setting the system property ```kotest framework sourceref disable=true```

wasyl · Answer

I ll check that slightly smiling face

sam · Answer

You can do this inside your gradle file so that it won t affect running via the plugin ``` tasks named lt Test gt test useJUnitPlatform systemProperty kotest framework sourceref disable true ```

sam · Answer

If that doesn t help then yes we ll give up joy

wasyl · Answer

With this property set the tests are ~30 faster slightly smiling face

sam · Answer

niceeeee