https://kotlinlang.org logo
Channels
100daysofcode
100daysofkotlin
100daysofkotlin-2021
advent-of-code
aem
ai
alexa
algeria
algolialibraries
amsterdam
android
android-architecture
android-databinding
android-studio
androidgithubprojects
androidthings
androidx
androidx-xprocessing
anime
anko
announcements
apollo-kotlin
appintro
arabic
argentina
arkenv
arksemdevteam
armenia
arrow
arrow-contributors
arrow-meta
ass
atlanta
atm17
atrium
austin
australia
austria
awesome-kotlin
ballast
bangladesh
barcelona
bayarea
bazel
beepiz-libraries
belgium
benchmarks
berlin
big-data
books
boston
brazil
brikk
budapest
build
build-tools
bulgaria
bydgoszcz
cambodia
canada
carrat
carrat-dev
carrat-feed
chicago
chile
china
chucker
cincinnati-user-group
cli
clikt
cloudfoundry
cn
cobalt
code-coverage
codeforces
codemash-precompiler
codereview
codingame
codingconventions
coimbatore
collaborations
colombia
colorado
communities
competitive-programming
competitivecoding
compiler
compose
compose-android
compose-desktop
compose-hiring
compose-ios
compose-mp
compose-ui-showcase
compose-wear
compose-web
confetti
connect-audit-events
corda
cork
coroutines
couchbase
coursera
croatia
cryptography
cscenter-course-2016
cucumber-bdd
cyprus
czech
dagger
data2viz
databinding
datascience
dckotlin
debugging
decompose
decouple
denmark
deprecated
detekt
detekt-hint
dev-core
dfw
docs-revamped
dokka
domain-driven-design
doodle
dsl
dublin
dutch
eap
eclipse
ecuador
edinburgh
education
effective-kotlin
effectivekotlin
emacs
embedded-kotlin
estatik
event21-community-content
events
exposed
failgood
fb-internal-demo
feed
firebase
flow
fluid-libraries
forkhandles
forum
fosdem
fp-in-kotlin
framework-elide
freenode
french
fritz2
fuchsia
functional
funktionale
gamedev
ge-kotlin
general-advice
georgia
geospatial
german-lang
getting-started
github-workflows-kt
glance
godot-kotlin
google-io
gradle
graphic
graphkool
graphql
graphql-kotlin
graviton-browser
greece
grpc
gsoc
gui
hackathons
hacktoberfest
hamburg
hamkrest
helios
helsinki
hexagon
hibernate
hikari-cp
hire-me
hiring
hongkong
hoplite
http4k
hungary
hyderabad
image-processing
india
indonesia
inkremental
intellij
intellij-plugins
intellij-tricks
internships
introduce-yourself
io
ios
iran
israel
istanbulcoders
italian
jackson-kotlin
jadx
japanese
jasync-sql
java-to-kotlin-refactoring
javadevelopers
javafx
javalin
javascript
jdbi
jhipster-kotlin
jobsworldwide
jpa
jshdq
juul-libraries
jvm-ir-backend-feedback
jxadapter
k2-early-adopters
kaal
kafka
kakao
kalasim
kapt
karachi
karg
karlsruhe
kash_shell
kaskade
kbuild
kdbc
kgen-doc-tools
kgraphql
kinta
klaxon
klock
kloudformation
kmdc
kmm-español
kmongo
knbt
knote
koalaql
koans
kobalt
kobweb
kodein
kodex
kohesive
koin
koin-dev
komapper
kondor-json
kong
kontent
kontributors
korau
korean
korge
korim
korio
korlibs
korte
kotest
kotest-contributors
kotless
kotlick
kotlin-asia
kotlin-beam
kotlin-by-example
kotlin-csv
kotlin-data-storage
kotlin-foundation
kotlin-fuel
kotlin-in-action
kotlin-inject
kotlin-latam
kotlin-logging
kotlin-multiplatform-contest
kotlin-mumbai
kotlin-native
kotlin-pakistan
kotlin-plugin
kotlin-pune
kotlin-roadmap
kotlin-samples
kotlin-sap
kotlin-serbia
kotlin-spark
kotlin-szeged
kotlin-website
kotlinacademy
kotlinbot
kotlinconf
kotlindl
kotlinforbeginners
kotlingforbeginners
kotlinlondon
kotlinmad
kotlinprogrammers
kotlinsu
kotlintest
kotlintest-devs
kotlintlv
kotlinultimatechallenge
kotlinx-datetime
kotlinx-files
kotlinx-html
kotrix
kotson
kovenant
kprompt
kraph
krawler
kroto-plus
ksp
ktcc
ktfmt
ktlint
ktor
ktp
kubed
kug-leads
kug-torino
kvision
kweb
lambdaworld_cadiz
lanark
language-evolution
language-proposals
latvia
leakcanary
leedskotlinusergroup
lets-have-fun
libgdx
libkgd
library-development
lincheck
linkeddata
lithuania
london
losangeles
lottie
love
lychee
macedonia
machinelearningbawas
madrid
malaysia
mathematics
meetkotlin
memes
meta
metro-detroit
mexico
miami
micronaut
minnesota
minutest
mirror
mockk
moko
moldova
monsterpuzzle
montreal
moonbean
morocco
motionlayout
mpapt
mu
multiplatform
mumbai
munich
mvikotlin
mvrx
myndocs-oauth2-server
naming
navigation-architecture-component
nepal
new-mexico
new-zealand
newname
nigeria
nodejs
norway
npm-publish
nyc
oceania
ohio-kotlin-users
oldenburg
oolong
opensource
orbit-mvi
osgi
otpisani
package-search
pakistan
panamá
pattern-matching
pbandk
pdx
peru
philippines
phoenix
pinoy
pocketgitclient
polish
popkorn
portugal
practical-functional-programming
proguard
prozis-android-backup
pyhsikal
python
python-contributors
quasar
random
re
react
reaktive
realm
realworldkotlin
reductor
reduks
redux
redux-kotlin
refactoring-to-kotlin
reflect
refreshversions
reports
result
rethink
revolver
rhein-main
rocksdb
romania
room
rpi-pico
rsocket
russian
russian_feed
russian-kotlinasfirst
rx
rxjava
san-diego
science
scotland
scrcast
scrimage
script
scripting
seattle
serialization
server
sg-user-group
singapore
skia-wasm-interop-temp
skrape-it
slovak
snake
sofl-user-group
southafrica
spacemacs
spain
spanish
speaking
spek
spin
splitties
spotify-mobius
spring
spring-security
squarelibraries
stackoverflow
stacks
stayhungrystayfoolish
stdlib
stlouis
strife-discord-lib
strikt
students
stuttgart
sudan
swagger-gradle-codegen
swarm
sweden
swing
swiss-user-group
switzerland
talking-kotlin
tallinn
tampa
teamcity
tegal
tempe
tensorflow
terminal
test
testing
testtestest
texas
tgbotapi
thailand
tornadofx
touchlab-tools
training
tricity-kotlin-user-group
trójmiasto
truth
tunisia
turkey
turkiye
twitter-feed
uae
udacityindia
uk
ukrainian
uniflow
unkonf
uruguay
utah
uuid
vancouver
vankotlin
vertx
videos
vienna
vietnam
vim
vkug
vuejs
web-mpp
webassembly
webrtc
wimix_sentry
wwdc
zircon
Powered by
Title
w

wasyl

09/08/2020, 10:30 AM
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.
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
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
s

sam

09/08/2020, 5:05 PM
Can you clarify what you mean by running in the console.
do you mean ./gradlew check in a terminal ?
w

wasyl

09/09/2020, 6:46 AM
Yep,
./gradlew someProject:test
I’m not sure if related but I started profiling the tests to see what’s the issue
The longest single test takes 1 minut when running directly from Gradle, and spends vast majority of time in
testFinished
listener, figuring out failures:
This is just one block but it’s ~20s in several
describe
blocks side by side
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)
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)
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()
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
Seems like caching
Description#id()
is a pretty low-hanging fruit?
Aaaand with 4.2.4 we’re down with tests execution time from 5 minutes to one 🎉
👍 1
s

sam

09/09/2020, 12:23 PM
Perfect :)
w

wasyl

09/09/2020, 12:24 PM
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
s

sam

09/09/2020, 12:24 PM
Hmmm ok
Is locally using gradle as well
Or plugin only
w

wasyl

09/09/2020, 12:25 PM
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
Locally is Gradle as well, overall IDE was always fast so I’m not focusing on it at all
s

sam

09/09/2020, 12:25 PM
Agreed
Ok so could be jacoco
It does do jvm agent stuff
If you can turn it off for a single ci run to see
w

wasyl

09/09/2020, 12:27 PM
Yep I’ll check. Btw this is memory profiling results for my run
s

sam

09/09/2020, 12:28 PM
I will optimise that
What tool do you use to get that info
w

wasyl

09/09/2020, 12:28 PM
I installed
startup profiler
and manually modify jvmargs for the test task such that it attaches and samples from the start
s

sam

09/09/2020, 12:30 PM
Ok cool thanks
👍 1
w

wasyl

09/09/2020, 1:07 PM
For some tests using
forall
blocks I seem to also lose a bit of time in
isOnPath
btw
That’s again
id
calculation though, but it seems that the regex patter is created every time?
the
compile
is quite heavy so I suppose it could be cached as well
I also see quite some time in
Regex.replace
in the
id()
calculation, but I don’t see how to optimise it 🤔
s

sam

09/09/2020, 7:12 PM
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.
w

wasyl

09/09/2020, 8:27 PM
👍 thanks 🙂 Will try, I see 659 is not up yet though (and there are some failed CI runs for the two related commits fyi)
s

sam

09/09/2020, 8:27 PM
Yeah sorry about that. I've fixed it and will kick off another run shortly.
👍 1
4.3.0.664-SNAPSHOT
w

wasyl

09/10/2020, 9:06 AM
Thank you 🙂 Not very scientific as I don’t have numbers, but I do see a reasonable improvement with the snapshot
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)
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 😉
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
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
s

sam

09/10/2020, 10:40 PM
sourceref might be able to be lazy, I will test that
r

reevn

09/11/2020, 9:20 AM
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
s

sam

09/12/2020, 6:38 PM
Had a play with source ref but it has to stay as it's needed for both the junit integration and the intellij plugin.
😢 1
I've released 4.2.5 with the other perf enhancements though
🎉 2
w

wasyl

09/13/2020, 1:39 PM
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!
s

sam

09/13/2020, 2:27 PM
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
w

wasyl

09/14/2020, 7:14 AM
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 😕
s

sam

09/14/2020, 8:22 AM
I can test it locally as I'm in jdk11
Seems to be 4x faster on short stacks
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.
w

wasyl

09/14/2020, 9:50 AM
It’s interesting, I don’t see any speedup at all 🤔
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
s

sam

09/14/2020, 9:53 AM
So if you add jdk9 dep (and you're on jdk9 of course!) then it should detect the stack walker and use it
Otherwise it will silently fall back to thread.stacktrace
w

wasyl

09/14/2020, 10:15 AM
I verified that indeed stack walker is used, but unfortunately the tests take exactly the same amount of time 😕 sorry
That’s on jdk 11
s

sam

09/14/2020, 10:26 AM
hmmm ok, that's a shame. I have a test that does 100,000 source refs and the time dropped from 2500 to 700
w

wasyl

09/14/2020, 10:28 AM
Yep I saw that one, also on my machine (jdk8) it ran for about 6.5 seconds, which is also interesting.
s

sam

09/14/2020, 10:29 AM
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
It's main use is in the intellij plugin so the test results can link back to the test file
w

wasyl

09/14/2020, 10:29 AM
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?
s

sam

09/14/2020, 10:32 AM
yes possible
w

wasyl

09/14/2020, 10:32 AM
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
s

sam

09/14/2020, 10:32 AM
If you wait for build
4.3.0.679-SNAPSHOT
and then try setting the system property
kotest.framework.sourceref.disable=true
👍 1
w

wasyl

09/14/2020, 10:33 AM
I’ll check that 🙂
s

sam

09/14/2020, 10:33 AM
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")
}
👌 1
If that doesn't help then yes, we'll give up 😂
w

wasyl

09/14/2020, 11:50 AM
With this property set, the tests are ~30% faster 🙂
🎉 2
s

sam

09/14/2020, 11:53 AM
niceeeee