https://kotlinlang.org logo
#kotest
Title
# kotest
j

Jonathan Lennox

05/26/2022, 7:36 PM
I'm porting some unit tests from Kotest 4.6 to Kotest 5.3, and I've discovered that one of my tests is taking a hugely longer time to run with the new kotest - i.e. from 1.5 seconds with kotest 4.6, to 90 seconds with kotest 5.3 on my test AWS host. Any idea what could be causing this?
Oddly this only happens if it's part of my whole unit test - if I run it individually with
mvn -Dtest=TccGeneratorNodeTest test
it takes only 1.5 seconds again.
So maybe something else in the test suite is interfering?
The one notable change I had to do for the port to kotest 5.3 was to add
suspend
to the declarations of the test's
beforeSpec
methods.
The other odd thing is that this problem only occurs on a Linux box - on my x64 Mac it doesn't happen.
s

sam

05/27/2022, 5:46 PM
Linux box here, running the suite : [INFO] Tests run: 9, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.687 s - in org.jitsi.nlj.transform.node.incoming.TccGeneratorNodeTest [INFO] Running org.jitsi.nlj.util.TimeExpiringCacheTest
0.6 seconds for that test
j

Jonathan Lennox

05/28/2022, 11:48 PM
Huh, even weirder. Which JVM?
And this was with the version of the PR that used the 5.3.0 test suite?
s

sam

05/29/2022, 2:26 PM
Ok I was on master. Switching to your
bump-kotlin
branch:
Copy code
[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[WARNING] Corrupted STDOUT by directly writing to native stream in forked JVM 1. See FAQ web page and the dump file /home/sam/development/workspace/jitsi-media-transform/target/surefire-reports/2022-05-29T09-26-30_623-jvmRun1.dumpstream
[INFO] 
[INFO] Results:
[INFO] 
[INFO] Tests run: 0, Failures: 0, Errors: 0, Skipped: 0
[INFO] 
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  29.472 s
[INFO] Finished at: 2022-05-29T09:26:32-05:00
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.22.0:test (default-test) on project jitsi-media-transform: There are test failures.
[ERROR] 
[ERROR] Please refer to /home/sam/development/workspace/jitsi-media-transform/target/surefire-reports for the individual test results.
[ERROR] Please refer to dump files (if any exist) [date]-jvmRun[N].dump, [date].dumpstream and [date]-jvmRun[N].dumpstream.
[ERROR] There was an error in the forked process
[ERROR] io/kotlintest/specs/ShouldSpec
[ERROR] org.apache.maven.surefire.booter.SurefireBooterForkException: There was an error in the forked process
[ERROR] io/kotlintest/specs/ShouldSpec
[ERROR] 	at org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:658)
[ERROR] 	at org.apache.maven.plugin.surefire.booterclient.ForkStarter.fork(ForkStarter.java:533)
[ERROR] 	at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:278)
[ERROR] 	at org.apache.maven.plugin.surefire.booterclient.ForkStarter.run(ForkStarter.java:244)
[ERROR] 	at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeProvider(AbstractSurefireMojo.java:1194)
[ERROR] 	at org.apache.maven.plugin.surefire.AbstractSurefireMojo.executeAfterPreconditionsChecked(AbstractSurefireMojo.java:1022)
[ERROR] 	at org.apache.maven.plugin.surefire.AbstractSurefireMojo.execute(AbstractSurefireMojo.java:868)
[ERROR] 	at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:137)
j

Jonathan Lennox

05/29/2022, 2:33 PM
Just to confirm, this is the tag which has the ktor 5 build, right? I rolled the bump-kotlin branch back to ktor 4 so I could merge it.
s

sam

05/29/2022, 2:33 PM
I just looked at the PR branch.
j

Jonathan Lennox

05/29/2022, 2:33 PM
I now have a bump-kotlin-ktor5 branch so as to avoid confusion.
s

sam

05/29/2022, 2:34 PM
ok let me try that
j

Jonathan Lennox

05/29/2022, 2:34 PM
What JVM version are you using?
s

sam

05/29/2022, 2:35 PM
openjdk 11.0.12 2021-07-20 OpenJDK Runtime Environment 18.9 (build 11.0.12+7) OpenJDK 64-Bit Server VM 18.9 (build 11.0.12+7, mixed mode)
same fork error on your new branch btw
j

Jonathan Lennox

05/29/2022, 2:35 PM
Hm, that's what I have too.
Two other notable things: we have GitHub integration tests for these PR, and when this PR ran there, the testing took six hours and then was killed by GitHub.
Which is much worse than my AWS instance, so there's something variable here.
s

sam

05/29/2022, 2:37 PM
I'll try removing some tests until it at least passes
something is odd in your project as it just killed my intellij
j

Jonathan Lennox

05/29/2022, 2:45 PM
Huh
When you ran the tests?
s

sam

05/29/2022, 2:45 PM
just trying to parse out a file
might just be a weird one off
I don't know if this is contribuing to your issues:
Copy code
[WARNING] Corrupted STDOUT by directly writing to native stream in forked JVM 1. See FAQ web page and the dump file /home/sam/development/workspace/jitsi-media-transform/target/surefire-reports/2022-05-29T09-46-40_841-jvmRun1.dumpstream
j

Jonathan Lennox

05/29/2022, 2:47 PM
That's not happening for me, so something's different there too.
s

sam

05/29/2022, 2:48 PM
do you have a custom stdout logger ?
j

Jonathan Lennox

05/29/2022, 2:49 PM
I don't think so...what's the message in the dumpstream?
s

sam

05/29/2022, 2:50 PM
it just passed so now I don't have it
let me start adding things back in
did you explicitly enable kotest logging btw ?
j

Jonathan Lennox

05/29/2022, 2:50 PM
No
s

sam

05/29/2022, 2:51 PM
ok that's a bug unless I have it enabled on my system as an env var
j

Jonathan Lennox

05/29/2022, 2:51 PM
(Well, I didn't write the original kotest here, I'm just porting it to kotest 5, but I don't think so.)
s

sam

05/29/2022, 2:51 PM
(a bug in kotest to be clear)
ok never mind I have it enabled KOTEST_DEBUG=true
j

Jonathan Lennox

05/29/2022, 2:52 PM
I wonder if it's outputting something in the forked process
s

sam

05/29/2022, 2:52 PM
I wasn't doing maven clean test before
just maven test
so it's possible those errors were from the other branch 🤦🏻‍♂️
Copy code
[INFO] Tests run: 116, Failures: 0, Errors: 0, Skipped: 0
[INFO] 
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  01:11 min
[INFO] Finished at: 2022-05-29T09:56:17-05:00
[INFO] ------------------------------------------------------------------------
that's for everything but your tcc test
j

Jonathan Lennox

05/29/2022, 2:57 PM
Ok, this is interesting, I tried adding an
<argLine>-Xmx1G</argLine>
to the maven-surefire-plugin configuration, and the tests now seem to take much longer on my Mac. I suspect something's leaking memory, and if JVM's heap is too small the GC starts thrashing?
s

sam

05/29/2022, 2:57 PM
you could fire up the tests and launch visualvm
attach it to the test jvm and see what gc is doign
ok with all tests enabled:
Copy code
[INFO] Tests run: 125, Failures: 0, Errors: 0, Skipped: 0
[INFO] 
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  01:04 min
[INFO] Finished at: 2022-05-29T09:57:46-05:00
[INFO] ------------------------------------------------------------------------
I have an i9 16 core with 32gb btw
j

Jonathan Lennox

05/29/2022, 2:58 PM
Yeah, this would explain why it's been fine on my Mac, it's got 32G too.
s

sam

05/29/2022, 2:59 PM
when I run stuff on GHA I always bump the VM to 3gb
It's gradle but I do this
Copy code
GRADLE_OPTS: -Dorg.gradle.configureondemand=false -Dorg.gradle.parallel=false -Dkotlin.incremental=false -Dorg.gradle.jvmargs="-Xmx3g -XX:MaxPermSize=2048m -XX:+HeapDumpOnOutOfMemoryError -Dfile.encoding=UTF-8"
j

Jonathan Lennox

05/29/2022, 3:15 PM
I'll see if I can give the visualVm a try later
(Have to run now.). Thank you!
👍🏻 1
Okay, some experimentation shows it definitely has to do with heap size. When I set heap size to
<argLine>-Xmx1994391552</argLine>
(the default MaxHeapSize on my AWS instance) it runs slowly. When I set it to
<argLine>-Xmx1822425088</argLine>
(the default MaxHeapSize on the Azure instances GitHub uses) it takes interminably long. I'll see if I can attach and profile it.
Looking at a memory snapshot in YourKit I see
io.mockk.impl.stub.SpyKStub
has a retained memory size of 1,930,015,280 bytes.
🤯 1
90 Views