https://kotlinlang.org logo
Join Slack
Powered by
I'm porting some unit tests from Kotest 4.6 to Kot...
# kotest
j
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
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
Huh, even weirder. Which JVM?
And this was with the version of the PR that used the 5.3.0 test suite?
s
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
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
I just looked at the PR branch.
j
I now have a bump-kotlin-ktor5 branch so as to avoid confusion.
s
ok let me try that
j
What JVM version are you using?
s
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
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
I'll try removing some tests until it at least passes
something is odd in your project as it just killed my intellij
j
Huh
When you ran the tests?
s
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
That's not happening for me, so something's different there too.
s
do you have a custom stdout logger ?
j
I don't think so...what's the message in the dumpstream?
s
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
No
s
ok that's a bug unless I have it enabled on my system as an env var
j
(Well, I didn't write the original kotest here, I'm just porting it to kotest 5, but I don't think so.)
s
(a bug in kotest to be clear)
ok never mind I have it enabled KOTEST_DEBUG=true
j
I wonder if it's outputting something in the forked process
s
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
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
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
Yeah, this would explain why it's been fine on my Mac, it's got 32G too.
s
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
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
111 Views
Open in Slack
PreviousNext
Powered by