Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Tests have huge delay, and "Default test timeout: 600000ms" shows #1355

Closed
tom-jb opened this issue Apr 5, 2020 · 55 comments
Closed

Tests have huge delay, and "Default test timeout: 600000ms" shows #1355

tom-jb opened this issue Apr 5, 2020 · 55 comments
Labels
bug 🐛 Issues that report a problem or error in the code. multiplatform-android 🌐

Comments

@tom-jb
Copy link

tom-jb commented Apr 5, 2020 •
edited

I'm trying Kotest for the first time (version 4.0.2). I created a new project in Android Studio 3.6.2, using Gradle 5.6.4. I added the basic example tests:

class MyTests : StringSpec({
    "length should return size of string" {
        "hello".length shouldBe 5
    }
    "startsWith should test for a prefix" {
        "world" should startWith("wor")
    }
})

I ran the tests, and they passed, but they took several seconds to run. The following was printed in the Android Studio 'Run' window:

~~~ Kotest Configuration ~~~
-> Parallelism: 1 thread(s)
-> Default test timeout: 600000ms
-> Default test order: TestCaseOrder
-> Default isolation mode: IsolationMode
-> Global soft assertations: False
-> Write spec failure file: False
-> Fail on ignored tests: False
-> Spec execution order: LexicographicSpecExecutionOrder
-> Extensions
  - io.kotest.core.extensions.SystemPropertyTagExtension
  - io.kotest.core.extensions.RuntimeTagExtension
  - io.kotest.core.extensions.IgnoredSpecDiscoveryExtension
  - io.kotest.core.extensions.TagFilteredDiscoveryExtension

There is no exception message; just the above. I get the same output if I run gradlew test from the command line.

I tried both the JUnit 5 runner and the JUnit 4 runner, with the same results each time. I also tried Gradle 6.3, with the same results.

The following SO question seems to be the same issue:

https://stackoverflow.com/questions/60351366/kotest-freezes-after-migrating-to-4-0-0-beta1-on-testdebugunittest-task
@LeoColman LeoColman added multiplatform-android 🌐 bug 🐛 Issues that report a problem or error in the code. labels Apr 5, 2020
@LeoColman
Copy link
Member

LeoColman commented Apr 5, 2020 •
edited

On the SO message you linked, @sksamuel answered:

If you're using gradle < 6, set a system property called kotest.gradle5.compatibility=true and make sure you're using 4.0.2. This is a workaround for a bug in gradle 5.x

Could you try to do that and see if things work?

My suggestion would be to try to migrate to a newer gradle version and ensure that IntelliJ actually is using the new version, via a sync or an invalidate/restart

@sksamuel
Copy link
Member

sksamuel commented Apr 5, 2020 via email

@LeoColman
Copy link
Member

Looks like he tried 6.3 as well but this issue is usually caused by gradle
5 bugs

Many times IntelliJ/Android Studio just don't sync the project for some unknown reason. That's why I suggested ensuring it's actually using gradle 6

@tom-jb
Copy link
Author

tom-jb commented Apr 5, 2020

I just tried Gradle 6.3 again, by using this line in gradle-wrapper.properties:

distributionUrl=https\://services.gradle.org/distributions/gradle-6.3-all.zip

I then did a manual sync and invalidated caches (and restarted), but the problem continues.

If you're using gradle < 6, set a system property called kotest.gradle5.compatibility=true and make sure you're using 4.0.2. This is a workaround for a bug in gradle 5.x

Sorry, I am really awful at Gradle stuff. How do I set this property?

@tom-jb
Copy link
Author

tom-jb commented Apr 5, 2020 •
edited

I just switched back to Gradle 5.6.4 and then added the line kotest.gradle5.compatibility=true to 'gradle.properties' and did a sync, and the problem still occurs.

# Project-wide Gradle settings.
# IDE (e.g. Android Studio) users:
# Gradle settings configured through the IDE *will override*
# any settings specified in this file.
# For more details on how to configure your build environment visit
# http://www.gradle.org/docs/current/userguide/build_environment.html
# Specifies the JVM arguments used for the daemon process.
# The setting is particularly useful for tweaking memory settings.
org.gradle.jvmargs=-Xmx1536m
# When configured, Gradle will run in incubating parallel mode.
# This option should only be used with decoupled projects. More details, visit
# http://www.gradle.org/docs/current/userguide/multi_project_builds.html#sec:decoupled_projects
# org.gradle.parallel=true
# AndroidX package structure to make it clearer which packages are bundled with the
# Android operating system, and which are packaged with your app's APK
# https://developer.android.com/topic/libraries/support-library/androidx-rn
android.useAndroidX=true
# Automatically convert third-party libraries to use AndroidX
android.enableJetifier=true
# Kotlin code style for this project: "official" or "obsolete":
kotlin.code.style=official
kotest.gradle5.compatibility=true

@tom-jb
Copy link
Author

tom-jb commented Apr 9, 2020

Are you guys able to reproduce this? Is there anything else I can try? I simply cannot use Kotest without a huge delay before the tests run. I'm not sure exactly why, and this is my first ever time trying Kotest.

@sksamuel
Copy link
Member

sksamuel commented Apr 9, 2020

How long is the huge delay would you say ?

@tom-jb
Copy link
Author

tom-jb commented Apr 10, 2020

It's around six seconds.

@sksamuel
Copy link
Member

sksamuel commented Apr 10, 2020 via email

@tom-jb
Copy link
Author

tom-jb commented Apr 10, 2020

This happens in a brand new project in Android Studio. There is almost no code.

I'll try setting the debug variable tomorrow; I'm not at a computer right now, unfortunately.

@sksamuel
Copy link
Member

sksamuel commented Apr 10, 2020 via email

@tom-jb
Copy link
Author

tom-jb commented Apr 10, 2020

Okay, I set KOTEST_DEBUG=true in the Run task in Android Studio and received the folllowing output.

(Note that I didn't see any output until after the long delay. The Android Studio 'Run' tool window just shows "Instantiating tests..." for several seconds, and there is no output during this time.)

invokeBeforeAll
~~~ Kotest Configuration ~~~
-> Parallelism: 1 thread(s)
-> Default test timeout: 600000ms
-> Default test order: TestCaseOrder
-> Default isolation mode: IsolationMode
-> Global soft assertations: False
-> Write spec failure file: False
-> Fail on ignored tests: False
-> Spec execution order: LexicographicSpecExecutionOrder
-> Extensions
  - io.kotest.core.extensions.SystemPropertyTagExtension
  - io.kotest.core.extensions.RuntimeTagExtension
  - io.kotest.core.extensions.IgnoredSpecDiscoveryExtension
  - io.kotest.core.extensions.TagFilteredDiscoveryExtension

Submitting 1 specs
Waiting for spec execution to terminate
Spec executor has terminated null
Waiting for spec execution to terminate
Executing spec class com.example.MyTests
Executing engine listener callback:specStarted class com.example.MyTests
Executing notifyPrepareSpec
Executing engine listener callback:specInstantiated spec:com.example.MyTests@40637cda
invokeBeforeSpec com.example.MyTests@40637cda
Materialized roots: [RootTest(testCase=TestCase(description=Description(parents=[com.example.MyTests], name=length should return size of string), spec=com.example.MyTests@40637cda, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=15, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null), order=0), RootTest(testCase=TestCase(description=Description(parents=[com.example.MyTests], name=startsWith should test for a prefix), spec=com.example.MyTests@40637cda, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=18, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null), order=1)]
Executing test RootTest(testCase=TestCase(description=Description(parents=[com.example.MyTests], name=length should return size of string), spec=com.example.MyTests@40637cda, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=15, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null), order=0)
Executing active test TestCase(description=Description(parents=[com.example.MyTests], name=length should return size of string), spec=com.example.MyTests@40637cda, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=15, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null)

invokeTestCase TestCase(description=Description(parents=[com.example.MyTests], name=length should return size of string), spec=com.example.MyTests@40637cda, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=15, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null)
Scheduler will interrupt this execution in 600sms
Test completed with result TestResult(status=Success, error=null, reason=null, duration=55.6ms)

Executing test RootTest(testCase=TestCase(description=Description(parents=[com.example.MyTests], name=startsWith should test for a prefix), spec=com.example.MyTests@40637cda, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=18, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null), order=1)
Executing active test TestCase(description=Description(parents=[com.example.MyTests], name=startsWith should test for a prefix), spec=com.example.MyTests@40637cda, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=18, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null)

invokeTestCase TestCase(description=Description(parents=[com.example.MyTests], name=startsWith should test for a prefix), spec=com.example.MyTests@40637cda, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=18, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null)
Scheduler will interrupt this execution in 600sms
Test completed with result TestResult(status=Success, error=null, reason=null, duration=10.5ms)

invokeAfterSpec com.example.MyTests@40637cda
Executing notifyFinalizeSpec
Executing engine listener callback:specFinished class com.example.MyTests
Spec executor has terminated null
invokeAfterAll

Process finished with exit code 0

Here is the test code again:

class MyTests : StringSpec({
    "length should return size of string" {
        "hello".length shouldBe 5
    }
    "startsWith should test for a prefix" {
        "world" should startWith("wor")
    }
})

@sksamuel
Copy link
Member

Thanks for doing that. It seems that the full output was missed. Perhaps that flag was only active for the run task. Can you add that same KOTEST_DEBUG as an env to the entire build, and make sure you're running without gradle cache enabled. Once I can see the full output I should know what is taking so long.

@tom-jb
Copy link
Author

tom-jb commented Apr 11, 2020

Sorry, could you tell me how to set KOTEST_DEBUG for the entire build? I tried googling but cannot figure it out.

@sksamuel
Copy link
Member

sksamuel commented Apr 11, 2020 via email

@tom-jb
Copy link
Author

tom-jb commented Apr 11, 2020

I'm running via Android Studio, though I could run via the command line as well.

@sksamuel
Copy link
Member

sksamuel commented Apr 11, 2020 via email

@tom-jb
Copy link
Author

tom-jb commented Apr 11, 2020

Okay, I've tried this, but setting KOTEST_DEBUG doesn't seem to change the output in build/test-results/testDebugUnitTest/TEST-com.example.MyTests, which is always this:

invokeBeforeAll
~~~ Kotest Configuration ~~~
-> Parallelism: 1 thread(s)
-> Default test timeout: 600000ms
-> Default test order: TestCaseOrder
-> Default isolation mode: IsolationMode
-> Global soft assertations: False
-> Write spec failure file: False
-> Fail on ignored tests: False
-> Spec execution order: LexicographicSpecExecutionOrder
-> Extensions
- io.kotest.core.extensions.SystemPropertyTagExtension
- io.kotest.core.extensions.RuntimeTagExtension
- io.kotest.core.extensions.IgnoredSpecDiscoveryExtension
- io.kotest.core.extensions.TagFilteredDiscoveryExtension

Submitting 1 specs
Waiting for spec execution to terminate
Spec executor has terminated null
Waiting for spec execution to terminate
Executing spec class com.example.MyTests
Executing engine listener callback:specStarted class com.example.MyTests
Executing notifyPrepareSpec
Executing engine listener callback:specInstantiated spec:com.example.MyTests@78db5725
invokeBeforeSpec com.example.MyTests@78db5725
Materialized roots: [RootTest(testCase=TestCase(description=Description(parents=[com.example.MyTests], name=length should return size of string), spec=com.example.MyTests@78db5725, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=15, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null), order=0), RootTest(testCase=TestCase(description=Description(parents=[com.example.MyTests], name=startsWith should test for a prefix), spec=com.example.MyTests@78db5725, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=18, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null), order=1)]
Executing test RootTest(testCase=TestCase(description=Description(parents=[com.example.MyTests], name=length should return size of string), spec=com.example.MyTests@78db5725, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=15, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null), order=0)
Executing active test TestCase(description=Description(parents=[com.example.MyTests], name=length should return size of string), spec=com.example.MyTests@78db5725, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=15, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null)

invokeTestCase TestCase(description=Description(parents=[com.example.MyTests], name=length should return size of string), spec=com.example.MyTests@78db5725, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=15, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null)
Scheduler will interrupt this execution in 600sms
Test completed with result TestResult(status=Success, error=null, reason=null, duration=91.9ms)

Executing test RootTest(testCase=TestCase(description=Description(parents=[com.example.MyTests], name=startsWith should test for a prefix), spec=com.example.MyTests@78db5725, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=18, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null), order=1)
Executing active test TestCase(description=Description(parents=[com.example.MyTests], name=startsWith should test for a prefix), spec=com.example.MyTests@78db5725, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=18, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null)

invokeTestCase TestCase(description=Description(parents=[com.example.MyTests], name=startsWith should test for a prefix), spec=com.example.MyTests@78db5725, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=18, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null)
Scheduler will interrupt this execution in 600sms
Test completed with result TestResult(status=Success, error=null, reason=null, duration=11.8ms)

invokeAfterSpec com.example.MyTests@78db5725
Executing notifyFinalizeSpec
Executing engine listener callback:specFinished class com.example.MyTests
Spec executor has terminated null
invokeAfterAll

This also seems to be the same as the previous output.

Also, the delay doesn't appear to be happening when running from the command line, which suggests a problem with Android Studio, but then I've run several testing libraries in Android Studio without this problem. It's only Kotest that has this big delay.

@sksamuel
Copy link
Member

sksamuel commented Apr 11, 2020 via email

@tom-jb
Copy link
Author

tom-jb commented Apr 11, 2020

I wish I could help more. :(

I wonder whether there is a way of setting this variable for the whole build within Android Studio? I tried searching for a way to set it in build.gradle, but nothing seems to work.

@sksamuel
Copy link
Member

sksamuel commented Apr 11, 2020 via email

@tom-jb
Copy link
Author

tom-jb commented Apr 11, 2020

Thanks. Unfortunately, that only shows the usual "Configuration" message in the 'Run' window in Android Studio:

~~~ Kotest Configuration ~~~
-> Parallelism: 1 thread(s)
-> Default test timeout: 600000ms
-> Default test order: TestCaseOrder
-> Default isolation mode: IsolationMode
-> Global soft assertations: False
-> Write spec failure file: False
-> Fail on ignored tests: False
-> Spec execution order: LexicographicSpecExecutionOrder
-> Extensions
  - io.kotest.core.extensions.SystemPropertyTagExtension
  - io.kotest.core.extensions.RuntimeTagExtension
  - io.kotest.core.extensions.IgnoredSpecDiscoveryExtension
  - io.kotest.core.extensions.TagFilteredDiscoveryExtension

I can't see any other output.

@sksamuel
Copy link
Member

It didn't pick up the system property then.
Gradle can be a bit funny.
What about setting the env directly in the run config inside android studio ?

image

@tom-jb
Copy link
Author

tom-jb commented Apr 11, 2020

Okay, I recreated that Gradle 'check' task exactly as in your screenshot, but unfortunately I still don't see any mention of the word 'Scan':

Testing started at 07:09 ...
Executing tasks: [check] in project C:\Test\app

> Task :app:preBuild UP-TO-DATE
> Task :app:preDebugBuild UP-TO-DATE
> Task :app:compileDebugAidl NO-SOURCE
> Task :app:compileDebugRenderscript NO-SOURCE
> Task :app:dataBindingMergeDependencyArtifactsDebug UP-TO-DATE
> Task :app:generateDebugResValues UP-TO-DATE
> Task :app:generateDebugResources UP-TO-DATE
> Task :app:generateDebugBuildConfig UP-TO-DATE
> Task :app:dataBindingMergeGenClassesDebug UP-TO-DATE
> Task :app:mergeDebugResources UP-TO-DATE
> Task :app:dataBindingGenBaseClassesDebug UP-TO-DATE
> Task :app:mainApkListPersistenceDebug UP-TO-DATE
> Task :app:createDebugCompatibleScreenManifests UP-TO-DATE
> Task :app:extractDeepLinksDebug UP-TO-DATE
> Task :app:preReleaseBuild UP-TO-DATE
> Task :app:compileReleaseAidl NO-SOURCE
> Task :app:processDebugManifest UP-TO-DATE
> Task :app:processDebugResources UP-TO-DATE
> Task :app:compileDebugKotlin UP-TO-DATE
> Task :app:javaPreCompileDebug UP-TO-DATE
> Task :app:compileDebugJavaWithJavac UP-TO-DATE
> Task :app:compileReleaseRenderscript NO-SOURCE
> Task :app:dataBindingMergeDependencyArtifactsRelease UP-TO-DATE
> Task :app:dataBindingMergeGenClassesRelease UP-TO-DATE
> Task :app:generateReleaseResValues UP-TO-DATE
> Task :app:generateReleaseResources UP-TO-DATE
> Task :app:mergeReleaseResources UP-TO-DATE
> Task :app:dataBindingGenBaseClassesRelease UP-TO-DATE
> Task :app:generateReleaseBuildConfig UP-TO-DATE
> Task :app:mainApkListPersistenceRelease UP-TO-DATE
> Task :app:createReleaseCompatibleScreenManifests UP-TO-DATE
> Task :app:extractDeepLinksRelease UP-TO-DATE
> Task :app:processReleaseManifest UP-TO-DATE
> Task :app:processReleaseResources UP-TO-DATE
> Task :app:compileReleaseKotlin UP-TO-DATE
> Task :app:javaPreCompileRelease UP-TO-DATE
> Task :app:compileReleaseJavaWithJavac UP-TO-DATE
> Task :app:prepareLintJar UP-TO-DATE
> Task :app:lint
Ran lint on variant debug: 0 issues found
Ran lint on variant release: 0 issues found
Wrote HTML report to file:///C:/Test/app/build/reports/lint-results.html
Wrote XML report to file:///C:/Test/app/build/reports/lint-results.xml
> Task :app:compileDebugUnitTestKotlin
> Task :app:preDebugUnitTestBuild UP-TO-DATE
> Task :app:processDebugJavaRes NO-SOURCE
> Task :app:processDebugUnitTestJavaRes NO-SOURCE
> Task :app:compileReleaseUnitTestKotlin
> Task :app:preReleaseUnitTestBuild UP-TO-DATE
> Task :app:javaPreCompileDebugUnitTest
> Task :app:compileDebugUnitTestJavaWithJavac NO-SOURCE
> Task :app:testDebugUnitTest
invokeBeforeAll
~~~ Kotest Configuration ~~~
-> Parallelism: 1 thread(s)
-> Default test timeout: 600000ms
-> Default test order: TestCaseOrder
-> Default isolation mode: IsolationMode
-> Global soft assertations: False
-> Write spec failure file: False
-> Fail on ignored tests: False
-> Spec execution order: LexicographicSpecExecutionOrder
-> Extensions
  - io.kotest.core.extensions.SystemPropertyTagExtension
  - io.kotest.core.extensions.RuntimeTagExtension
  - io.kotest.core.extensions.IgnoredSpecDiscoveryExtension
  - io.kotest.core.extensions.TagFilteredDiscoveryExtension

Submitting 1 specs
Waiting for spec execution to terminate
Spec executor has terminated null
Waiting for spec execution to terminate
Executing spec class com.example.MyTests
Executing engine listener callback:specStarted class com.example.MyTests
Executing notifyPrepareSpec
Executing engine listener callback:specInstantiated spec:com.example.MyTests@2ae53ac3
invokeBeforeSpec com.example.MyTests@2ae53ac3
Materialized roots: [RootTest(testCase=TestCase(description=Description(parents=[com.example.MyTests], name=length should return size of string), spec=com.example.MyTests@2ae53ac3, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=15, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null), order=0), RootTest(testCase=TestCase(description=Description(parents=[com.example.MyTests], name=startsWith should test for a prefix), spec=com.example.MyTests@2ae53ac3, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=18, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null), order=1)]
Executing test RootTest(testCase=TestCase(description=Description(parents=[com.example.MyTests], name=length should return size of string), spec=com.example.MyTests@2ae53ac3, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=15, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null), order=0)
Executing active test TestCase(description=Description(parents=[com.example.MyTests], name=length should return size of string), spec=com.example.MyTests@2ae53ac3, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=15, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null)
invokeTestCase TestCase(description=Description(parents=[com.example.MyTests], name=length should return size of string), spec=com.example.MyTests@2ae53ac3, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=15, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null)
Scheduler will interrupt this execution in 600sms
Test completed with result TestResult(status=Success, error=null, reason=null, duration=52.8ms)
Executing test RootTest(testCase=TestCase(description=Description(parents=[com.example.MyTests], name=startsWith should test for a prefix), spec=com.example.MyTests@2ae53ac3, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=18, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null), order=1)
Executing active test TestCase(description=Description(parents=[com.example.MyTests], name=startsWith should test for a prefix), spec=com.example.MyTests@2ae53ac3, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=18, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null)
invokeTestCase TestCase(description=Description(parents=[com.example.MyTests], name=startsWith should test for a prefix), spec=com.example.MyTests@2ae53ac3, test=io.kotest.core.test.TestContext.() -> kotlin.Unit, source=SourceRef(lineNumber=18, fileName=RandomExpressionGeneratorTests.kt), type=Test, config=TestCaseConfig(enabled=true, invocations=1, threads=1, timeout=null, tags=[], listeners=[], extensions=[], enabledIf=(io.kotest.core.test.TestCase) -> kotlin.Boolean), factoryId=null, assertionMode=null)
Scheduler will interrupt this execution in 600sms
Test completed with result TestResult(status=Success, error=null, reason=null, duration=36.9ms)
invokeAfterSpec com.example.MyTests@2ae53ac3
Executing notifyFinalizeSpec
Executing engine listener callback:specFinished class com.example.MyTests
Spec executor has terminated null
invokeAfterAll
> Task :app:processReleaseJavaRes NO-SOURCE
> Task :app:processReleaseUnitTestJavaRes NO-SOURCE
> Task :app:javaPreCompileReleaseUnitTest
> Task :app:compileReleaseUnitTestJavaWithJavac NO-SOURCE
> Task :app:testReleaseUnitTest UP-TO-DATE
> Task :app:test
> Task :app:check
BUILD SUCCESSFUL in 13s
36 actionable tasks: 6 executed, 30 up-to-date
07:09:58: Task execution finished 'check'.

@sksamuel
Copy link
Member

sksamuel commented Apr 11, 2020 via email

@tom-jb
Copy link
Author

tom-jb commented Apr 11, 2020

Yeah, Windows 10.

@OliverCulleyDeLange
Copy link

Wanted to add a partial +1 to this.

Same setup here - Windows 10, android studio, Kotest 4.0.2, gradle 5.6.4
I get the same ~5 - 6 seconds delay before tests actually run where android studio says Instantiating tests.... However i do actually get the tests to run and they pass/fail accordingly.

I ugraded to gradle 6.3 after reading that SO post, but it hasn't made any noticable difference.

@sksamuel
Copy link
Member

sksamuel commented Apr 12, 2020 via email

@sksamuel
Copy link
Member

sksamuel commented Apr 12, 2020 via email

@tom-jb
Copy link
Author

tom-jb commented Apr 12, 2020

However i do actually get the tests to run and they pass/fail accordingly.

Yes, the same applies to me. The tests run fine and pass; the only problem is that I see "Instantiating tests…" for several seconds before every run.

@sksamuel
Copy link
Member

sksamuel commented Apr 12, 2020 via email

@OliverCulleyDeLange
Copy link

Bit of a strange result, with the new version, my test files aren't recognised as test files anymore and can't be 'run' so i can't compare run times in Android Studio.

@sksamuel
Copy link
Member

sksamuel commented Apr 12, 2020 via email

@OliverCulleyDeLange
Copy link

Its hard to compare, as i don't use gradle to run testsas its much more convenient to run through Android Studio if i'm running a subset of tests for example.
They take roughly the same time, so ~15 seconds to run 1 test either from Android Studio or Gradle.

@tom-jb
Copy link
Author

tom-jb commented Apr 12, 2020

When I try the following, I get 'ERROR: Failed to resolve' on both lines:

testImplementation 'io.kotest:kotest-runner-junit4-jvm:4.1.0.225-SNAPSHOT' // for kotest framework
testImplementation 'io.kotest:kotest-assertions-core-jvm:4.1.0.225-SNAPSHOT' // for kotest core jvm assertions

However, like Oliver, I run tests from Android Studio anyway. And as far as I can tell this delay happens only when I run from Android Studio.

On the other hand, I did just try Kotlintest 3.4.2, and I found that the delay there is much shorter. Rather than seeing "Instantiating tests…" for about six seconds, I see it for about two seconds instead.

This is still longer than I see it with plain JUnit, where I see "Instantiating tests…" for less than a second, but it is much quicker than with Kotest 4.

@sksamuel
Copy link
Member

sksamuel commented Apr 13, 2020 via email

@tom-jb
Copy link
Author

tom-jb commented Apr 14, 2020 •
edited

Okay, I just added the Sonatype repository and tried 4.1.0.225-SNAPSHOT.

I ran the tests in Android Studio, and they ran and passed, but the 6-second "Instantiating tests..." delay was still there.

@sksamuel
Copy link
Member

Thanks for trying that. I think that rules out classgraph just being slow in older versions.
Can you look at intellij on the project view under external libs and get a list of all the libraries being pulled in. Like this:

image

I am wondering if there are a ton of android libraries we can blacklist so they're never scanned for tests (like we do with java, javax, and so on).

@tom-jb
Copy link
Author

tom-jb commented Apr 14, 2020

Okay, here it is:

@sksamuel
Copy link
Member

sksamuel commented Apr 14, 2020 via email

@tom-jb
Copy link
Author

tom-jb commented Apr 14, 2020

Thanks, I'll try it straightaway.

sksamuel added a commit that referenced this issue Apr 14, 2020
@sksamuel
Added android packages to classpath blacklist #1355
e19c5d4
@sksamuel
Copy link
Member

sksamuel commented Apr 15, 2020 via email

@tom-jb
Copy link
Author

tom-jb commented Apr 15, 2020

I'm trying 4.1.0.245-SNAPSHOT right now.

It's telling me it can't find StringSpec (and FunSpec and so on).

In the import io.kotest.core.spec.style.StringSpec statement, Android Studio is highlighting 'core' in red, suggesting that 'core' does not exist.

@tom-jb
Copy link
Author

tom-jb commented Apr 15, 2020

Okay, I fixed the above by changing "junit4" to "junit5" in the following:

testImplementation 'io.kotest:kotest-runner-junit4-jvm:4.1.0.245-SNAPSHOT'

Now the tests run and pass. However, the huge delay is still present. In fact, it seems slightly longer now (eight seconds instead of six seconds), but I could be mistaken about it being slightly longer.

@sksamuel
Copy link
Member

sksamuel commented Apr 15, 2020 via email

@sksamuel
Copy link
Member

Did we ever get closer to solving this ?

@sksamuel
Copy link
Member

4.1.0 is out if you want to try that.

@klesniewski
Copy link

I experience similar issue, although with non-Android, plain Kotlin/JVM project. From running the test task to executing first test it takes around 12 seconds, where it takes 6 seconds before it starts executing spec and then another 6 seconds before running the first test in the spec. The last number is surely affected by starting a Postgres container using TestContainers.
I experience the problem with Kotest 4.0.2 and it is still there after upgrading to Kotest 4.1.1.

OS: Windows 10 x64
JVM: 14
Gradle: 6.3
Kotlin: 1.3.71
Kotest: 4.1.1

Here is a recording from test run:
kotest-slow-init

You can also see I set KOTEST_DEBUG env var, but I don't see any additional output. I tried the same in IntelliJ also without result. Any ideas how can I gather more details on the problem?

@sksamuel
Copy link
Member

sksamuel commented Jul 18, 2020 via email

@sksamuel
Copy link
Member

There's been some changes in architecture in the 4.2.x releases. Is this still happening on say 4.2.2 ?

@Animeshz
Copy link

Seems like yes, still 600 seconds on 4.2.5

@gindex
Copy link

gindex commented Oct 27, 2020

Similar issues with kotest 4.3.0

@sksamuel
Copy link
Member

Can you try 4.3.1. I'm hoping #1788 has solved this.

@gindex
Copy link

gindex commented Nov 4, 2020

Looks like the issues are gone with 4.3.1 👍

@sksamuel
Copy link
Member

sksamuel commented Nov 5, 2020

Great.

@sksamuel sksamuel closed this as completed Nov 5, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug 🐛 Issues that report a problem or error in the code. multiplatform-android 🌐
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
7 participants
@sksamuel @LeoColman @gindex @OliverCulleyDeLange @klesniewski @Animeshz @tom-jb