From c7239ac4915df344add7386c8aa19038499f5e4b Mon Sep 17 00:00:00 2001 From: Vsevolod Tolstopyatov Date: Mon, 10 Dec 2018 11:41:00 +0300 Subject: [PATCH 1/7] Debug agent to track alive coroutines * Can be installed dynamically or from command line * Captures coroutine creation stacktrace and stores it in completion, automatically enhancing stacktrace recovery mechanism * Allows to dump and introspect all active coroutines * Allows to dump Job hierarchy * When installed from command line, dumps all coroutines on kill -5 * Probe support in undispatched coroutines --- README.md | 2 + RELEASE.md | 2 +- binary-compatibility-validator/build.gradle | 1 + .../kotlinx-coroutines-core.txt | 1 + .../kotlinx-coroutines-debug.txt | 39 +++ .../src/JobSupport.kt | 5 +- .../src/internal/ProbesSupport.common.kt | 9 + .../src/intrinsics/Undispatched.kt | 30 +- core/README.md | 4 +- core/kotlinx-coroutines-core/src/Debug.kt | 4 +- .../src/internal/ProbesSupport.kt | 11 + .../src/internal/StackTraceRecovery.kt | 9 +- core/kotlinx-coroutines-debug/README.md | 118 ++++++++ core/kotlinx-coroutines-debug/build.gradle | 18 ++ .../src/debug/AgentPremain.kt | 25 ++ .../src/debug/CoroutineState.kt | 84 ++++++ .../src/debug/DebugProbes.kt | 123 ++++++++ .../src/debug/internal/DebugProbesImpl.kt | 282 ++++++++++++++++++ .../src/debug/internal/NoOpProbes.kt | 19 ++ .../test/debug/CoroutinesDumpTest.kt | 154 ++++++++++ .../test/debug/DebugProbesTest.kt | 104 +++++++ .../test/debug/HierarchyToStringTest.kt | 81 +++++ .../test/debug/SanitizedProbesTest.kt | 114 +++++++ .../test/debug/StartModeProbesTest.kt | 157 ++++++++++ .../test/debug/StracktraceUtils.kt | 101 +++++++ gradle.properties | 1 + .../src/internal/ProbesSupport.kt | 10 + knit/resources/knit.properties | 2 +- .../src/internal/ProbesSupport.kt | 10 + settings.gradle | 1 + 30 files changed, 1500 insertions(+), 21 deletions(-) create mode 100644 binary-compatibility-validator/reference-public-api/kotlinx-coroutines-debug.txt create mode 100644 common/kotlinx-coroutines-core-common/src/internal/ProbesSupport.common.kt create mode 100644 core/kotlinx-coroutines-core/src/internal/ProbesSupport.kt create mode 100644 core/kotlinx-coroutines-debug/README.md create mode 100644 core/kotlinx-coroutines-debug/build.gradle create mode 100644 core/kotlinx-coroutines-debug/src/debug/AgentPremain.kt create mode 100644 core/kotlinx-coroutines-debug/src/debug/CoroutineState.kt create mode 100644 core/kotlinx-coroutines-debug/src/debug/DebugProbes.kt create mode 100644 core/kotlinx-coroutines-debug/src/debug/internal/DebugProbesImpl.kt create mode 100644 core/kotlinx-coroutines-debug/src/debug/internal/NoOpProbes.kt create mode 100644 core/kotlinx-coroutines-debug/test/debug/CoroutinesDumpTest.kt create mode 100644 core/kotlinx-coroutines-debug/test/debug/DebugProbesTest.kt create mode 100644 core/kotlinx-coroutines-debug/test/debug/HierarchyToStringTest.kt create mode 100644 core/kotlinx-coroutines-debug/test/debug/SanitizedProbesTest.kt create mode 100644 core/kotlinx-coroutines-debug/test/debug/StartModeProbesTest.kt create mode 100644 core/kotlinx-coroutines-debug/test/debug/StracktraceUtils.kt create mode 100644 js/kotlinx-coroutines-core-js/src/internal/ProbesSupport.kt create mode 100644 native/kotlinx-coroutines-core-native/src/internal/ProbesSupport.kt diff --git a/README.md b/README.md index e2e9364d07..72ddc6b266 100644 --- a/README.md +++ b/README.md @@ -31,6 +31,8 @@ GlobalScope.launch { * [core](core/README.md) — Kotlin/JVM implementation of common coroutines with additional features: * `Dispatchers.IO` dispatcher for blocking coroutines; * `Executor.asCoroutineDispatcher()` extension, custom thread pools, and more. +* [debug](core/README.md) — debug utilities for coroutines. + * `DebugProbes` API to probe, keep track of, print and dump active coroutines. * [js](js/README.md) — Kotlin/JS implementation of common coroutines with `Promise` support. * [native](native/README.md) — Kotlin/Native implementation of common coroutines with `runBlocking` single-threaded event loop. * [reactive](reactive/README.md) — modules that provide builders and iteration support for various reactive streams libraries: diff --git a/RELEASE.md b/RELEASE.md index 11c5af519b..3ab6c94de3 100644 --- a/RELEASE.md +++ b/RELEASE.md @@ -12,7 +12,7 @@ To release new `` of `kotlinx-coroutines`: `git merge origin/master` 4. Search & replace `` with `` across the project files. Should replace in: - * [`README.md`](README.md) + * [`README.md`](README.md) (native, core, test, debug, modules) * [`coroutines-guide.md`](docs/coroutines-guide.md) * [`gradle.properties`](gradle.properties) * [`ui/kotlinx-coroutines-android/example-app/gradle.properties`](ui/kotlinx-coroutines-android/example-app/gradle.properties) diff --git a/binary-compatibility-validator/build.gradle b/binary-compatibility-validator/build.gradle index 785848c142..2aa9e145da 100644 --- a/binary-compatibility-validator/build.gradle +++ b/binary-compatibility-validator/build.gradle @@ -13,6 +13,7 @@ dependencies { testCompile "org.jetbrains.kotlin:kotlin-test-junit:$kotlin_version" testArtifacts project(':kotlinx-coroutines-core') + testArtifacts project(':kotlinx-coroutines-debug') testArtifacts project(':kotlinx-coroutines-reactive') testArtifacts project(':kotlinx-coroutines-reactor') diff --git a/binary-compatibility-validator/reference-public-api/kotlinx-coroutines-core.txt b/binary-compatibility-validator/reference-public-api/kotlinx-coroutines-core.txt index d7b990c417..21e8e59076 100644 --- a/binary-compatibility-validator/reference-public-api/kotlinx-coroutines-core.txt +++ b/binary-compatibility-validator/reference-public-api/kotlinx-coroutines-core.txt @@ -349,6 +349,7 @@ public class kotlinx/coroutines/JobSupport : kotlinx/coroutines/ChildJob, kotlin public fun plus (Lkotlinx/coroutines/Job;)Lkotlinx/coroutines/Job; public final fun registerSelectClause0 (Lkotlinx/coroutines/selects/SelectInstance;Lkotlin/jvm/functions/Function1;)V public final fun start ()Z + public final fun toDebugString ()Ljava/lang/String; public fun toString ()Ljava/lang/String; } diff --git a/binary-compatibility-validator/reference-public-api/kotlinx-coroutines-debug.txt b/binary-compatibility-validator/reference-public-api/kotlinx-coroutines-debug.txt new file mode 100644 index 0000000000..fa607fbdfa --- /dev/null +++ b/binary-compatibility-validator/reference-public-api/kotlinx-coroutines-debug.txt @@ -0,0 +1,39 @@ +public final class kotlinx/coroutines/debug/CoroutineState { + public final fun component1 ()Lkotlin/coroutines/Continuation; + public final fun component2 ()Ljava/util/List; + public final fun copy (Lkotlin/coroutines/Continuation;Ljava/util/List;J)Lkotlinx/coroutines/debug/CoroutineState; + public static synthetic fun copy$default (Lkotlinx/coroutines/debug/CoroutineState;Lkotlin/coroutines/Continuation;Ljava/util/List;JILjava/lang/Object;)Lkotlinx/coroutines/debug/CoroutineState; + public fun equals (Ljava/lang/Object;)Z + public final fun getContinuation ()Lkotlin/coroutines/Continuation; + public final fun getCreationStackTrace ()Ljava/util/List; + public final fun getJob ()Lkotlinx/coroutines/Job; + public final fun getJobOrNull ()Lkotlinx/coroutines/Job; + public final fun getState ()Lkotlinx/coroutines/debug/State; + public fun hashCode ()I + public final fun lastObservedStackTrace ()Ljava/util/List; + public fun toString ()Ljava/lang/String; +} + +public final class kotlinx/coroutines/debug/DebugProbes { + public static final field INSTANCE Lkotlinx/coroutines/debug/DebugProbes; + public final fun dumpCoroutines (Ljava/io/PrintStream;)V + public static synthetic fun dumpCoroutines$default (Lkotlinx/coroutines/debug/DebugProbes;Ljava/io/PrintStream;ILjava/lang/Object;)V + public final fun dumpCoroutinesState ()Ljava/util/List; + public final fun getSanitizeStackTraces ()Z + public final fun hierarchyToString (Lkotlinx/coroutines/Job;)Ljava/lang/String; + public final fun install ()V + public final fun printHierarchy (Lkotlinx/coroutines/Job;Ljava/io/PrintStream;)V + public static synthetic fun printHierarchy$default (Lkotlinx/coroutines/debug/DebugProbes;Lkotlinx/coroutines/Job;Ljava/io/PrintStream;ILjava/lang/Object;)V + public final fun setSanitizeStackTraces (Z)V + public final fun uninstall ()V + public final fun withDebugProbes (Lkotlin/jvm/functions/Function0;)V +} + +public final class kotlinx/coroutines/debug/State : java/lang/Enum { + public static final field CREATED Lkotlinx/coroutines/debug/State; + public static final field RUNNING Lkotlinx/coroutines/debug/State; + public static final field SUSPENDED Lkotlinx/coroutines/debug/State; + public static fun valueOf (Ljava/lang/String;)Lkotlinx/coroutines/debug/State; + public static fun values ()[Lkotlinx/coroutines/debug/State; +} + diff --git a/common/kotlinx-coroutines-core-common/src/JobSupport.kt b/common/kotlinx-coroutines-core-common/src/JobSupport.kt index 011c9cf4f1..9ca9385820 100644 --- a/common/kotlinx-coroutines-core-common/src/JobSupport.kt +++ b/common/kotlinx-coroutines-core-common/src/JobSupport.kt @@ -925,7 +925,10 @@ public open class JobSupport constructor(active: Boolean) : Job, ChildJob, Paren // for nicer debugging public override fun toString(): String = - "${nameString()}{${stateString(state)}}@$hexAddress" + "${toDebugString()}@$hexAddress" + + @InternalCoroutinesApi + public fun toDebugString(): String = "${nameString()}{${stateString(state)}}" /** * @suppress **This is unstable API and it is subject to change.** diff --git a/common/kotlinx-coroutines-core-common/src/internal/ProbesSupport.common.kt b/common/kotlinx-coroutines-core-common/src/internal/ProbesSupport.common.kt new file mode 100644 index 0000000000..1124ff313b --- /dev/null +++ b/common/kotlinx-coroutines-core-common/src/internal/ProbesSupport.common.kt @@ -0,0 +1,9 @@ +/* + * Copyright 2016-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license. + */ + +package kotlinx.coroutines.internal + +import kotlin.coroutines.* + +internal expect inline fun probeCoroutineCreated(completion: Continuation): Continuation diff --git a/common/kotlinx-coroutines-core-common/src/intrinsics/Undispatched.kt b/common/kotlinx-coroutines-core-common/src/intrinsics/Undispatched.kt index fcfe8545a6..19dc6d28f0 100644 --- a/common/kotlinx-coroutines-core-common/src/intrinsics/Undispatched.kt +++ b/common/kotlinx-coroutines-core-common/src/intrinsics/Undispatched.kt @@ -15,8 +15,8 @@ import kotlin.coroutines.intrinsics.* * It does not use [ContinuationInterceptor] and does not update context of the current thread. */ internal fun (suspend () -> T).startCoroutineUnintercepted(completion: Continuation) { - startDirect(completion) { - startCoroutineUninterceptedOrReturn(completion) + startDirect(completion) { actualCompletion -> + startCoroutineUninterceptedOrReturn(actualCompletion) } } @@ -26,8 +26,8 @@ internal fun (suspend () -> T).startCoroutineUnintercepted(completion: Conti * It does not use [ContinuationInterceptor] and does not update context of the current thread. */ internal fun (suspend (R) -> T).startCoroutineUnintercepted(receiver: R, completion: Continuation) { - startDirect(completion) { - startCoroutineUninterceptedOrReturn(receiver, completion) + startDirect(completion) { actualCompletion -> + startCoroutineUninterceptedOrReturn(receiver, actualCompletion) } } @@ -37,9 +37,9 @@ internal fun (suspend (R) -> T).startCoroutineUnintercepted(receiver: R, * It does not use [ContinuationInterceptor], but updates the context of the current thread for the new coroutine. */ internal fun (suspend () -> T).startCoroutineUndispatched(completion: Continuation) { - startDirect(completion) { + startDirect(completion) { actualCompletion -> withCoroutineContext(completion.context, null) { - startCoroutineUninterceptedOrReturn(completion) + startCoroutineUninterceptedOrReturn(actualCompletion) } } } @@ -50,23 +50,29 @@ internal fun (suspend () -> T).startCoroutineUndispatched(completion: Contin * It does not use [ContinuationInterceptor], but updates the context of the current thread for the new coroutine. */ internal fun (suspend (R) -> T).startCoroutineUndispatched(receiver: R, completion: Continuation) { - startDirect(completion) { + startDirect(completion) { actualCompletion -> withCoroutineContext(completion.context, null) { - startCoroutineUninterceptedOrReturn(receiver, completion) + startCoroutineUninterceptedOrReturn(receiver, actualCompletion) } } } -private inline fun startDirect(completion: Continuation, block: () -> Any?) { +/** + * Starts given [block] immediately in the current stack-frame until first suspension point. + * This method supports debug probes and thus can intercept completion, thus completion is provide + * as the parameter of [block]. + */ +private inline fun startDirect(completion: Continuation, block: (Continuation) -> Any?) { + val actualCompletion = probeCoroutineCreated(completion) val value = try { - block() + block(actualCompletion) } catch (e: Throwable) { - completion.resumeWithException(e) + actualCompletion.resumeWithException(e) return } if (value !== COROUTINE_SUSPENDED) { @Suppress("UNCHECKED_CAST") - completion.resume(value as T) + actualCompletion.resume(value as T) } } diff --git a/core/README.md b/core/README.md index 4f353a01d3..0386912b2a 100644 --- a/core/README.md +++ b/core/README.md @@ -5,5 +5,5 @@ Module name below corresponds to the artifact name in Maven/Gradle. ## Modules -* [kotlinx-coroutines-core](kotlinx-coroutines-core/README.md) -- core coroutine builders and synchronization primitives. - +* [kotlinx-coroutines-core](kotlinx-coroutines-core/README.md) — core coroutine builders and synchronization primitives. +* [kotlinx-coroutines-debug](kotlinx-coroutines-debug/README.md) — coroutines debug utilities. \ No newline at end of file diff --git a/core/kotlinx-coroutines-core/src/Debug.kt b/core/kotlinx-coroutines-core/src/Debug.kt index 3796c400db..a1f53cd776 100644 --- a/core/kotlinx-coroutines-core/src/Debug.kt +++ b/core/kotlinx-coroutines-core/src/Debug.kt @@ -41,6 +41,7 @@ public const val DEBUG_PROPERTY_VALUE_ON = "on" */ public const val DEBUG_PROPERTY_VALUE_OFF = "off" +@JvmField internal val DEBUG = systemProp(DEBUG_PROPERTY_NAME).let { value -> when (value) { DEBUG_PROPERTY_VALUE_AUTO, null -> CoroutineId::class.java.desiredAssertionStatus() @@ -50,7 +51,8 @@ internal val DEBUG = systemProp(DEBUG_PROPERTY_NAME).let { value -> } } -internal val RECOVER_STACKTRACE = systemProp(STACKTRACE_RECOVERY_PROPERTY_NAME, true) +@JvmField +internal val RECOVER_STACKTRACES = systemProp(STACKTRACE_RECOVERY_PROPERTY_NAME, true) // internal debugging tools diff --git a/core/kotlinx-coroutines-core/src/internal/ProbesSupport.kt b/core/kotlinx-coroutines-core/src/internal/ProbesSupport.kt new file mode 100644 index 0000000000..f3c548e008 --- /dev/null +++ b/core/kotlinx-coroutines-core/src/internal/ProbesSupport.kt @@ -0,0 +1,11 @@ +/* + * Copyright 2016-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license. + */ +@file:Suppress("NOTHING_TO_INLINE", "INVISIBLE_REFERENCE", "INVISIBLE_MEMBER") + +package kotlinx.coroutines.internal + +import kotlin.coroutines.* +import kotlin.coroutines.jvm.internal.probeCoroutineCreated as probe + +internal actual inline fun probeCoroutineCreated(completion: Continuation): Continuation = probe(completion) \ No newline at end of file diff --git a/core/kotlinx-coroutines-core/src/internal/StackTraceRecovery.kt b/core/kotlinx-coroutines-core/src/internal/StackTraceRecovery.kt index fdfa69c401..0b3181f302 100644 --- a/core/kotlinx-coroutines-core/src/internal/StackTraceRecovery.kt +++ b/core/kotlinx-coroutines-core/src/internal/StackTraceRecovery.kt @@ -165,7 +165,7 @@ internal actual fun unwrap(exception: E): E { } private fun recoveryDisabled(exception: E) = - !RECOVER_STACKTRACE || !DEBUG || exception is CancellationException || exception is NonRecoverableThrowable + !RECOVER_STACKTRACES || !DEBUG || exception is CancellationException || exception is NonRecoverableThrowable private fun createStackTrace(continuation: CoroutineStackFrame): ArrayDeque { val stack = ArrayDeque() @@ -179,14 +179,17 @@ private fun createStackTrace(continuation: CoroutineStackFrame): ArrayDeque.frameIndex(methodName: String) = indexOfFirst { methodName == it.className } diff --git a/core/kotlinx-coroutines-debug/README.md b/core/kotlinx-coroutines-debug/README.md new file mode 100644 index 0000000000..e97f28f7c6 --- /dev/null +++ b/core/kotlinx-coroutines-debug/README.md @@ -0,0 +1,118 @@ +# Module kotlinx-coroutines-debug + +Debugging facilities for `kotlinx.coroutines` on JVM. + +### Overview +This module provides a debug JVM agent which allows to track and trace alive coroutines. +Main entry point to debug facilities is [DebugProbes]. +Call to [DebugProbes.install] installs debug agent via ByteBuddy and starts to spy on coroutines when they are created, suspended or resumed. + +After that you can use [DebugProbes.dumpCoroutines] to print all active (suspended or running) coroutines, including their state, creation and +suspension stacktraces. +Additionally, it is possible to process list of such coroutines via [DebugProbes.dumpCoroutinesState] or dump isolated parts +of coroutines hierarchies referenced by [Job] instance using [DebugProbes.printHierarchy]. + +### Using as JVM agent +Additionally, it is possible to use this module as standalone JVM agent to enable debug probes on the application startup. +You can run your application with additional argument: `-javaagent:kotlinx-coroutines-debug-1.1.0.jar`. +Additionally, on Linux and Mac OS X you can use `kill -5 $pid` command in order to force your application to print all alive coroutines. + + +### Example of usage + +Capabilities of this module can be demonstrated by the following example: +```kotlin +class Computation { + public fun computeValue(): Deferred = GlobalScope.async { + val firstPart = computeFirstPart() + val secondPart = computeSecondPart() + + combineResults(firstPart, secondPart) + } + + private suspend fun combineResults(firstPart: Deferred, secondPart: Deferred): String { + return firstPart.await() + secondPart.await() + } + + + private suspend fun CoroutineScope.computeFirstPart() = async { + delay(5000) + "4" + } + + private suspend fun CoroutineScope.computeSecondPart() = async { + delay(5000) + "2" + } +} + +fun main(args: Array) = runBlocking { + DebugProbes.install() + val computation = Computation() + val deferred = computation.computeValue() + + // Delay for some time + delay(1000) + + DebugProbes.dumpCoroutines() + + println("\nDumping only deferred") + DebugProbes.printHierarchy(deferred) +} +``` + +Printed result will be: +``` +Coroutines dump 2018/11/12 21:44:02 + +Coroutine "coroutine#2":DeferredCoroutine{Active}@1b26f7b2, state: SUSPENDED + at kotlinx.coroutines.DeferredCoroutine.await$suspendImpl(Builders.common.kt:99) + at Computation.combineResults(Example.kt:18) + at Computation$computeValue$1.invokeSuspend(Example.kt:14) + (Coroutine creation stacktrace) + at kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116) + at kotlinx.coroutines.intrinsics.CancellableKt.startCoroutineCancellable(Cancellable.kt:23) + at kotlinx.coroutines.CoroutineStart.invoke(CoroutineStart.kt:109) + at kotlinx.coroutines.AbstractCoroutine.start(AbstractCoroutine.kt:160) + at kotlinx.coroutines.BuildersKt__Builders_commonKt.async(Builders.common.kt:88) + at kotlinx.coroutines.BuildersKt.async(Unknown Source) + at kotlinx.coroutines.BuildersKt__Builders_commonKt.async$default(Builders.common.kt:81) + at kotlinx.coroutines.BuildersKt.async$default(Unknown Source) + at Computation.computeValue(Example.kt:10) + at ExampleKt$main$1.invokeSuspend(Example.kt:36) + at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:32) + at kotlinx.coroutines.DispatchedTask$DefaultImpls.run(Dispatched.kt:237) + at kotlinx.coroutines.DispatchedContinuation.run(Dispatched.kt:81) + at kotlinx.coroutines.EventLoopBase.processNextEvent(EventLoop.kt:123) + at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:69) + at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:45) + at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source) + at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:35) + at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source) + at ExampleKt.main(Example.kt:33) + +... More coroutines here ... + +Dumping only deferred +"coroutine#2":DeferredCoroutine{Active}, continuation is SUSPENDED at line kotlinx.coroutines.DeferredCoroutine.await$suspendImpl(Builders.common.kt:99) + "coroutine#3":DeferredCoroutine{Active}, continuation is SUSPENDED at line Computation$computeFirstPart$2.invokeSuspend(Example.kt:23) + "coroutine#4":DeferredCoroutine{Active}, continuation is SUSPENDED at line Computation$computeSecondPart$2.invokeSuspend(Example.kt:28) +``` + + +### Status of the API + +API is purely experimental and it is not guaranteed that it won't be changed (while it is marked as `@ExperimentalCoroutinesApi`). +Do not use this module in production environment and do not rely on the format of the data produced by [DebugProbes]. + + + +[Job]: https://kotlin.github.io/kotlinx.coroutines/kotlinx-coroutines-core/kotlinx.coroutines/-job/index.html + + +[DebugProbes]: https://kotlin.github.io/kotlinx.coroutines/kotlinx-coroutines-debug/kotlinx.coroutines.debug/-debug-probes/index.html +[DebugProbes.install]: https://kotlin.github.io/kotlinx.coroutines/kotlinx-coroutines-debug/kotlinx.coroutines.debug/-debug-probes/install.html +[DebugProbes.dumpCoroutines]: https://kotlin.github.io/kotlinx.coroutines/kotlinx-coroutines-debug/kotlinx.coroutines.debug/-debug-probes/dump-coroutines.html +[DebugProbes.dumpCoroutinesState]: https://kotlin.github.io/kotlinx.coroutines/kotlinx-coroutines-debug/kotlinx.coroutines.debug/-debug-probes/dump-coroutines-state.html +[DebugProbes.printHierarchy]: https://kotlin.github.io/kotlinx.coroutines/kotlinx-coroutines-debug/kotlinx.coroutines.debug/-debug-probes/print-hierarchy.html + diff --git a/core/kotlinx-coroutines-debug/build.gradle b/core/kotlinx-coroutines-debug/build.gradle new file mode 100644 index 0000000000..0b7a28c68e --- /dev/null +++ b/core/kotlinx-coroutines-debug/build.gradle @@ -0,0 +1,18 @@ +/* + * Copyright 2016-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license. + */ + +dependencies { + compile "net.bytebuddy:byte-buddy:$byte_buddy_version" + compile "net.bytebuddy:byte-buddy-agent:$byte_buddy_version" +} + +jar { + manifest { + attributes "Premain-Class": "kotlinx.coroutines.debug.AgentPremain" + attributes "Can-Redefine-Classes": "true" + // For local runs + // attributes "Main-Class": "kotlinx.coroutines.debug.Playground" + // attributes "Class-Path": configurations.compile.collect { it.absolutePath }.join(" ") + } +} diff --git a/core/kotlinx-coroutines-debug/src/debug/AgentPremain.kt b/core/kotlinx-coroutines-debug/src/debug/AgentPremain.kt new file mode 100644 index 0000000000..569134a0f5 --- /dev/null +++ b/core/kotlinx-coroutines-debug/src/debug/AgentPremain.kt @@ -0,0 +1,25 @@ +/* + * Copyright 2016-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license. + */ + +package kotlinx.coroutines.debug + +import net.bytebuddy.agent.* +import sun.misc.* +import java.lang.instrument.* + +@Suppress("unused") +internal object AgentPremain { + + @JvmStatic + public fun premain(args: String?, instrumentation: Instrumentation) { + Installer.premain(args, instrumentation) + DebugProbes.install() + installSignalHandler() + } + + private fun installSignalHandler() { + val signal = Signal("TRAP") // kill -5 + Signal.handle(signal, { DebugProbes.dumpCoroutines() }) + } +} diff --git a/core/kotlinx-coroutines-debug/src/debug/CoroutineState.kt b/core/kotlinx-coroutines-debug/src/debug/CoroutineState.kt new file mode 100644 index 0000000000..eb89a2f240 --- /dev/null +++ b/core/kotlinx-coroutines-debug/src/debug/CoroutineState.kt @@ -0,0 +1,84 @@ +/* + * Copyright 2016-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license. + */ + +@file:Suppress("PropertyName") + +package kotlinx.coroutines.debug + +import kotlinx.coroutines.* +import kotlinx.coroutines.internal.* +import kotlin.coroutines.* + +/** + * Class describing coroutine state. + */ +@ExperimentalCoroutinesApi +public data class CoroutineState internal constructor( + public val continuation: Continuation<*>, + public val creationStackTrace: List, + internal val sequenceNumber: Long) { + + /** + * [Job] associated with a current coroutine or [IllegalStateException] otherwise. + * May be later used in [DebugProbes.printHierarchy] + */ + public val job: Job get() = continuation.context[Job] ?: error("Continuation $continuation does not have a job") + + /** + * [Job] associated with a current coroutine or null. + * May be later used in [DebugProbes.printHierarchy] + */ + public val jobOrNull: Job? get() = continuation.context[Job] + + /** + * Last observed [state][State] of the coroutine. + */ + public val state: State get() = _state + + // Copy constructor + internal constructor(coroutine: Continuation<*>, state: CoroutineState) : this(coroutine, + state.creationStackTrace, + state.sequenceNumber) { + _state = state.state + this.lastObservedFrame = state.lastObservedFrame + } + + private var _state: State = State.CREATED + + private var lastObservedFrame: CoroutineStackFrame? = null + + internal fun updateState(state: State, frame: Continuation<*>) { + if (_state == state && lastObservedFrame != null) { + return + } + + _state = state + lastObservedFrame = frame as? CoroutineStackFrame + } + + /** + * Last observed stacktrace of the coroutine captured on its suspension or resumption point. + * It means that for [running][State.RUNNING] coroutines resulting stacktrace is inaccurate and + * reflects stacktrace of the resumption point, not the actual current stacktrace + */ + public fun lastObservedStackTrace(): List { + var frame: CoroutineStackFrame? = lastObservedFrame ?: return emptyList() + val result = ArrayList() + while (frame != null) { + frame.getStackTraceElement()?.let { result.add(sanitize(it)) } + frame = frame.callerFrame + } + + return result + } +} + +/** + * Current state of the coroutine. + */ +public enum class State { + CREATED, // Not yet started + RUNNING, + SUSPENDED +} diff --git a/core/kotlinx-coroutines-debug/src/debug/DebugProbes.kt b/core/kotlinx-coroutines-debug/src/debug/DebugProbes.kt new file mode 100644 index 0000000000..168c6072d4 --- /dev/null +++ b/core/kotlinx-coroutines-debug/src/debug/DebugProbes.kt @@ -0,0 +1,123 @@ +/* + * Copyright 2016-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license. + */ + +@file:Suppress("unused") + +package kotlinx.coroutines.debug + +import kotlinx.coroutines.* +import kotlinx.coroutines.debug.internal.* +import java.io.* +import java.lang.management.* +import java.util.* +import kotlin.coroutines.* + +/** + * Debug probes support. + * + * Debug probes is a dynamic attach mechanism, which installs multiple hooks into [Continuation] machinery. + * It slows down all coroutine-related code, but in return provides a lot of debug information, including + * asynchronous stack-traces and coroutine dumps (similar to [ThreadMXBean.dumpAllThreads] and `jstack` via [DebugProbes.dumpCoroutines]. + * + * Installed hooks: + * + * * `probeCoroutineResumed` is invoked on every [Continuation.resume]. + * * `probeCoroutineSuspended` is invoked on every continuation suspension. + * * `probeCoroutineCreated` is invoked on every coroutine creation using stdlib intrinsics. + * + * Overhead: + * * Every created continuation is stored in a weak hash map, thus adding additional GC pressure. + * * On every created continuation, stacktrace of the current thread is dumped. + * * On every `resume` and `suspend`, [WeakHashMap] is updated under a global lock. + * + * **WARNING: DO NOT USE DEBUG PROBES IN PRODUCTION ENVIRONMENT.** + */ +@ExperimentalCoroutinesApi +public object DebugProbes { + + /** + * Whether coroutine creation stacktraces should be sanitized. + * Sanitization removes all frames from `kotlinx.coroutines` package except + * the first one and the last one to simplify user's diagnostic. + */ + public var sanitizeStackTraces: Boolean = true + + /** + * Installs a [DebugProbes] instead of no-op stdlib probes by redefining + * debug probes class using the same class loader as one loaded [DebugProbes] class. + * + * **WARNING: DO NOT USE DEBUG PROBES IN PRODUCTION ENVIRONMENT** + */ + public fun install() { + DebugProbesImpl.install() + } + + /** + * Uninstall debug probes. + */ + public fun uninstall() { + DebugProbesImpl.uninstall() + } + + /** + * Invokes given block of code with installed debug probes and uninstall probes in the end. + * + * **WARNING: DO NOT USE DEBUG PROBES IN PRODUCTION ENVIRONMENT** + */ + public inline fun withDebugProbes(block: () -> Unit) { + install() + try { + block() + } finally { + uninstall() + } + } + + /** + * Returns string representation of the coroutines [job] hierarchy with additional debug information. + * Hierarchy is printed from the [job] as a root transitively to all children. + */ + public fun hierarchyToString(job: Job): String = DebugProbesImpl.hierarchyToString(job) + + /** + * Prints [job] hierarchy representation from [hierarchyToString] to given [out]. + */ + public fun printHierarchy(job: Job, out: PrintStream = System.out) = + out.println(DebugProbesImpl.hierarchyToString(job)) + + /** + * Returns all alive coroutine states. + * Resulting collection represents a consistent snapshot of all alive coroutines at the moment of invocation. + */ + public fun dumpCoroutinesState(): List = DebugProbesImpl.dumpCoroutinesState() + + /** + * Dumps all active coroutines into given output stream. + * Resulting collection represents a consistent snapshot of all alive coroutines at the moment of invocation. + * Output of this method is similar to `jstack` or full thread dump, so this method can and should be used as replacement to + * "Dump threads" action + * + * Example of the output: + * ``` + * Coroutines dump 2018/11/12 19:45:14 + * + * Coroutine "coroutine#42":StandaloneCoroutine{Active}@58fdd99, state: SUSPENDED + * at MyClass$awaitData.invokeSuspend(MyClass.kt:37) + * (Coroutine creation stacktrace) + * at MyClass.createIoRequest(MyClass.kt:142) + * at MyClass.fetchData(MyClass.kt:154) + * at MyClass.showData(MyClass.kt:31) + * + * ... + * ``` + */ + public fun dumpCoroutines(out: PrintStream = System.out) = DebugProbesImpl.dumpCoroutines(out) +} + +// Stubs which are injected as coroutine probes. Require direct match of signatures +internal fun probeCoroutineResumed(frame: Continuation<*>) = DebugProbesImpl.probeCoroutineResumed(frame) + +internal fun probeCoroutineSuspended(frame: Continuation<*>) = DebugProbesImpl.probeCoroutineSuspended(frame) +internal fun probeCoroutineCreated(completion: kotlin.coroutines.Continuation): kotlin.coroutines.Continuation = + DebugProbesImpl.probeCoroutineCreated(completion) diff --git a/core/kotlinx-coroutines-debug/src/debug/internal/DebugProbesImpl.kt b/core/kotlinx-coroutines-debug/src/debug/internal/DebugProbesImpl.kt new file mode 100644 index 0000000000..7f3be13f1b --- /dev/null +++ b/core/kotlinx-coroutines-debug/src/debug/internal/DebugProbesImpl.kt @@ -0,0 +1,282 @@ +/* + * Copyright 2016-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license. + */ + +package kotlinx.coroutines.debug.internal + +import kotlinx.coroutines.* +import kotlinx.coroutines.debug.* +import kotlinx.coroutines.internal.* +import net.bytebuddy.* +import net.bytebuddy.agent.* +import net.bytebuddy.dynamic.loading.* +import java.io.* +import java.text.* +import java.util.* +import kotlin.collections.ArrayList +import kotlin.coroutines.* + +/** + * Mirror of [DebugProbes] with actual implementation. + * [DebugProbes] are implemented with pimpl to simplify user-facing class and make it look simple and + * documented. + */ +internal object DebugProbesImpl { + private const val ARTIFICIAL_FRAME_MESSAGE = "Coroutine creation stacktrace" + private val dateFormat = SimpleDateFormat("yyyy/MM/dd HH:mm:ss") + private val capturedCoroutines = WeakHashMap, CoroutineState>() + private var installations = 0 + private val isInstalled: Boolean get() = installations > 0 + // To sort coroutines by creation order, used as unique id + private var sequenceNumber: Long = 0 + + @Synchronized + public fun install() { + if (++installations > 1) { + return + } + + ByteBuddyAgent.install() + val cl = Class.forName("kotlin.coroutines.jvm.internal.DebugProbesKt") + val cl2 = Class.forName("kotlinx.coroutines.debug.DebugProbesKt") + + ByteBuddy() + .redefine(cl2) + .name(cl.name) + .make() + .load(cl.classLoader, ClassReloadingStrategy.fromInstalledAgent()) + } + + @Synchronized + public fun uninstall() { + if (installations == 0) error("Agent was not installed") + if (--installations != 0) return + + capturedCoroutines.clear() + val cl = Class.forName("kotlin.coroutines.jvm.internal.DebugProbesKt") + val cl2 = Class.forName("kotlinx.coroutines.debug.internal.NoOpProbesKt") + + ByteBuddy() + .redefine(cl2) + .name(cl.name) + .make() + .load(cl.classLoader, ClassReloadingStrategy.fromInstalledAgent()) + } + + @Synchronized + public fun hierarchyToString(job: Job): String { + if (!isInstalled) { + error("Debug probes are not installed") + } + + val jobToStack = capturedCoroutines + .filterKeys { it.delegate.context[Job] != null } + .mapKeys { it.key.delegate.context[Job]!! } + + val sb = StringBuilder() + job.build(jobToStack, sb, "") + return sb.toString() + } + + private fun Job.build(map: Map, builder: StringBuilder, indent: String) { + val state = map[this] + builder.append(indent) + @Suppress("DEPRECATION_ERROR") + val str = if (this !is JobSupport) toString() else toDebugString() + if (state == null) { + builder.append("Coroutine: $str\n") + } else { + val element = state.lastObservedStackTrace().firstOrNull() + val contState = state.state + builder.append("$str, continuation is $contState at line $element\n") + } + + for (child in children) { + child.build(map, builder, indent + "\t") + } + } + + @Synchronized + public fun dumpCoroutinesState(): List { + if (!isInstalled) { + error("Debug probes are not installed") + } + + return capturedCoroutines.entries.asSequence() + .map { CoroutineState(it.key.delegate, it.value) } + .sortedBy { it.sequenceNumber } + .toList() + } + + @Synchronized + public fun dumpCoroutines(out: PrintStream) { + if (!isInstalled) { + error("Debug probes are not installed") + } + + // Avoid inference with other out/err invocations + val resultingString = buildString { + append("Coroutines dump ${dateFormat.format(System.currentTimeMillis())}") + + capturedCoroutines + .asSequence() + .sortedBy { it.value.sequenceNumber } + .forEach { (key, value) -> + val state = if (value.state == State.RUNNING) + "${value.state} (Last suspension stacktrace, not an actual stacktrace)" + else value.state.toString() + + append("\n\nCoroutine $key, state: $state") + val observedStackTrace = value.lastObservedStackTrace() + if (observedStackTrace.isEmpty()) { + append("\n\tat ${artificialFrame(ARTIFICIAL_FRAME_MESSAGE)}") + printStackTrace(value.creationStackTrace) + } else { + printStackTrace(value.lastObservedStackTrace()) + } + } + } + + // Move it out of synchronization? + out.println(resultingString) + } + + private fun StringBuilder.printStackTrace(frames: List) { + frames.forEach { frame -> + append("\n\tat $frame") + } + } + + @Synchronized + internal fun probeCoroutineResumed(frame: Continuation<*>) = updateState(frame, State.RUNNING) + + @Synchronized + internal fun probeCoroutineSuspended(frame: Continuation<*>) = updateState(frame, State.SUSPENDED) + + private fun updateState(frame: Continuation<*>, state: State) { + if (!isInstalled) { + return + } + + // Find ArtificialStackFrame of the coroutine + val owner = frame.owner() + val coroutineState = capturedCoroutines[owner] + if (coroutineState == null) { + warn(frame, state) + return + } + + coroutineState.updateState(state, frame) + } + + private fun Continuation<*>.owner(): ArtificialStackFrame<*>? { + var frame = this as? CoroutineStackFrame ?: return null + while (true) { + if (frame is ArtificialStackFrame<*>) return frame + val completion = frame.callerFrame ?: return null + frame = completion + } + } + + @Synchronized + internal fun probeCoroutineCreated(completion: Continuation): Continuation { + if (!isInstalled) { + return completion + } + + /* + * Here we replace completion with a sequence of CoroutineStackFrame objects + * which represents creation stacktrace, thus making stacktrace recovery mechanism + * even more verbose (it will attach coroutine creation stacktrace to all exceptions), + * and then using this artificial frame as an identifier of coroutineSuspended/resumed calls. + */ + val stacktrace = sanitizedStackTrace(Exception()) + val frames = ArrayList(stacktrace.size) + for ((index, frame) in stacktrace.reversed().withIndex()) { + frames += object : CoroutineStackFrame { + override val callerFrame: CoroutineStackFrame? + get() = if (index == 0) null else frames[index - 1] + + override fun getStackTraceElement(): StackTraceElement = frame + } + } + + val result = ArtificialStackFrame(completion, frames.last()!!) + capturedCoroutines[result] = CoroutineState(completion, stacktrace.slice(1 until stacktrace.size), ++sequenceNumber) + return result + } + + @Synchronized + private fun probeCoroutineCompleted(coroutine: ArtificialStackFrame<*>) { + capturedCoroutines.remove(coroutine) + } + + private class ArtificialStackFrame(val delegate: Continuation, frame: CoroutineStackFrame) : + Continuation by delegate, CoroutineStackFrame by frame { + + override fun resumeWith(result: Result) { + probeCoroutineCompleted(this) + delegate.resumeWith(result) + } + + override fun toString(): String = delegate.toString() + } + + private fun sanitizedStackTrace(throwable: T): Array { + val stackTrace = throwable.stackTrace + val size = stackTrace.size + + var probeIndex = -1 + for (i in 0 until size) { + val name = stackTrace[i].className + if ("kotlin.coroutines.jvm.internal.DebugProbesKt" == name) { + probeIndex = i + } + } + + if (!DebugProbes.sanitizeStackTraces) { + return Array(size - probeIndex) { + if (it == 0) artificialFrame(ARTIFICIAL_FRAME_MESSAGE) else stackTrace[it + probeIndex] + } + } + + /* + * Trim intervals of internal methods from the stacktrace (bounds are excluded from trimming) + * E.g. for sequence [e, i1, i2, i3, e, i4, e, i5, i6, e7] + * output will be [e, i1, i3, e, i4, e, i5, i7] + */ + val result = ArrayList(size - probeIndex + 1) + result += artificialFrame(ARTIFICIAL_FRAME_MESSAGE) + Thread.sleep(1) + var includeInternalFrame = true + for (i in (probeIndex + 1) until size - 1) { + val element = stackTrace[i] + if (!element.isInternalMethod) { + includeInternalFrame = true + result += element + continue + } + + if (includeInternalFrame) { + result += element + includeInternalFrame = false + } else if (stackTrace[i + 1].isInternalMethod) { + continue + } else { + result += element + includeInternalFrame = true + } + + } + + result += stackTrace[size - 1] + return result.toTypedArray() + } + + private val StackTraceElement.isInternalMethod: Boolean get() = className.startsWith("kotlinx.coroutines") + + private fun warn(frame: Continuation<*>, state: State) { + // TODO make this warning configurable or not a warning at all + System.err.println("Failed to find an owner of the frame $frame while transferring it to the state $state") + } +} diff --git a/core/kotlinx-coroutines-debug/src/debug/internal/NoOpProbes.kt b/core/kotlinx-coroutines-debug/src/debug/internal/NoOpProbes.kt new file mode 100644 index 0000000000..d32eeb674b --- /dev/null +++ b/core/kotlinx-coroutines-debug/src/debug/internal/NoOpProbes.kt @@ -0,0 +1,19 @@ +/* + * Copyright 2016-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license. + */ + +@file:Suppress("unused", "UNUSED_PARAMETER") + +package kotlinx.coroutines.debug.internal + +import kotlin.coroutines.* + +/* + * Empty class used to replace installed agent in the end of debug session + */ +@JvmName("probeCoroutineResumed") +internal fun probeCoroutineResumedNoOp(frame: Continuation<*>) = Unit +@JvmName("probeCoroutineSuspended") +internal fun probeCoroutineSuspendedNoOp(frame: Continuation<*>) = Unit +@JvmName("probeCoroutineCreated") +internal fun probeCoroutineCreatedNoOp(completion: kotlin.coroutines.Continuation): kotlin.coroutines.Continuation = completion diff --git a/core/kotlinx-coroutines-debug/test/debug/CoroutinesDumpTest.kt b/core/kotlinx-coroutines-debug/test/debug/CoroutinesDumpTest.kt new file mode 100644 index 0000000000..0b97a679c3 --- /dev/null +++ b/core/kotlinx-coroutines-debug/test/debug/CoroutinesDumpTest.kt @@ -0,0 +1,154 @@ +/* + * Copyright 2016-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license. + */ + +package kotlinx.coroutines.debug + +import kotlinx.coroutines.* +import org.junit.* +import org.junit.Test +import java.io.* +import kotlin.coroutines.* +import kotlin.test.* + +@Suppress("SUSPENSION_POINT_INSIDE_MONITOR") // bug in 1.3.0 FE +class CoroutinesDumpTest : TestBase() { + + private val monitor = Any() + + @Before + fun setUp() { + before() + DebugProbes.sanitizeStackTraces = false + DebugProbes.install() + } + + @After + fun tearDown() { + try { + DebugProbes.uninstall() + } finally { + onCompletion() + } + } + + @Test + fun testSuspendedCoroutine() = synchronized(monitor) { + val deferred = GlobalScope.async { + sleepingOuterMethod() + } + + awaitCoroutineStarted() + Thread.sleep(100) // Let delay be invoked + verifyDump( + "Coroutine \"coroutine#1\":DeferredCoroutine{Active}@1e4a7dd4, state: SUSPENDED\n" + + "\tat kotlinx.coroutines.debug.CoroutinesDumpTest.sleepingNestedMethod(CoroutinesDumpTest.kt:95)\n" + + "\tat kotlinx.coroutines.debug.CoroutinesDumpTest.sleepingOuterMethod(CoroutinesDumpTest.kt:88)\n" + + "\tat kotlinx.coroutines.debug.CoroutinesDumpTest\$testSuspendedCoroutine\$1\$deferred\$1.invokeSuspend(CoroutinesDumpTest.kt:29)\n" + + "\t(Coroutine creation stacktrace)\n" + + "\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n" + + "\tat kotlinx.coroutines.intrinsics.CancellableKt.startCoroutineCancellable(Cancellable.kt:23)\n" + + "\tat kotlinx.coroutines.CoroutineStart.invoke(CoroutineStart.kt:99)\n") + + val found = DebugProbes.dumpCoroutinesState().single { it.jobOrNull === deferred } + assertSame(deferred, found.job) + deferred.cancel() + runBlocking { deferred.join() } + } + + @Test + fun testRunningCoroutine() = synchronized(monitor) { + val deferred = GlobalScope.async { + activeMethod(shouldSuspend = false) + } + + awaitCoroutineStarted() + verifyDump( + "Coroutine \"coroutine#1\":DeferredCoroutine{Active}@1e4a7dd4, state: RUNNING (Last suspension stacktrace, not an actual stacktrace)\n" + + "\tat kotlinx.coroutines.debug.CoroutinesDumpTest\$testRunningCoroutine\$1\$deferred\$1.invokeSuspend(CoroutinesDumpTest.kt:49)\n" + + "\t(Coroutine creation stacktrace)\n" + + "\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n" + + "\tat kotlinx.coroutines.intrinsics.CancellableKt.startCoroutineCancellable(Cancellable.kt:23)\n" + + "\tat kotlinx.coroutines.CoroutineStart.invoke(CoroutineStart.kt:99)\n" + + "\tat kotlinx.coroutines.AbstractCoroutine.start(AbstractCoroutine.kt:148)\n" + + "\tat kotlinx.coroutines.BuildersKt__Builders_commonKt.async(Builders.common.kt)\n" + + "\tat kotlinx.coroutines.BuildersKt.async(Unknown Source)\n" + + "\tat kotlinx.coroutines.BuildersKt__Builders_commonKt.async\$default(Builders.common.kt)\n" + + "\tat kotlinx.coroutines.BuildersKt.async\$default(Unknown Source)\n" + + "\tat kotlinx.coroutines.debug.CoroutinesDumpTest.testRunningCoroutine(CoroutinesDumpTest.kt:49)") + deferred.cancel() + runBlocking { deferred.join() } + } + + @Test + fun testRunningCoroutineWithSuspensionPoint() = synchronized(monitor) { + val deferred = GlobalScope.async { + activeMethod(shouldSuspend = true) + } + + awaitCoroutineStarted() + verifyDump( + "Coroutine \"coroutine#1\":DeferredCoroutine{Active}@1e4a7dd4, state: RUNNING (Last suspension stacktrace, not an actual stacktrace)\n" + + "\tat kotlinx.coroutines.debug.CoroutinesDumpTest.nestedActiveMethod(CoroutinesDumpTest.kt:111)\n" + + "\tat kotlinx.coroutines.debug.CoroutinesDumpTest.activeMethod(CoroutinesDumpTest.kt:106)\n" + + "\tat kotlinx.coroutines.debug.CoroutinesDumpTest\$testRunningCoroutineWithSuspensionPoint\$1\$deferred\$1.invokeSuspend(CoroutinesDumpTest.kt:71)\n" + + "\t(Coroutine creation stacktrace)\n" + + "\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n" + + "\tat kotlinx.coroutines.intrinsics.CancellableKt.startCoroutineCancellable(Cancellable.kt:23)\n" + + "\tat kotlinx.coroutines.CoroutineStart.invoke(CoroutineStart.kt:99)\n" + + "\tat kotlinx.coroutines.AbstractCoroutine.start(AbstractCoroutine.kt:148)\n" + + "\tat kotlinx.coroutines.BuildersKt__Builders_commonKt.async(Builders.common.kt)\n" + + "\tat kotlinx.coroutines.BuildersKt.async(Unknown Source)\n" + + "\tat kotlinx.coroutines.BuildersKt__Builders_commonKt.async\$default(Builders.common.kt)\n" + + "\tat kotlinx.coroutines.BuildersKt.async\$default(Unknown Source)\n" + + "\tat kotlinx.coroutines.debug.CoroutinesDumpTest.testRunningCoroutineWithSuspensionPoint(CoroutinesDumpTest.kt:71)") + deferred.cancel() + runBlocking { deferred.join() } + } + + @Test + fun testFinishedCoroutineRemoved() = synchronized(monitor) { + val deferred = GlobalScope.async { + activeMethod(shouldSuspend = true) + } + + awaitCoroutineStarted() + deferred.cancel() + runBlocking { deferred.join() } + verifyDump() + } + + private suspend fun activeMethod(shouldSuspend: Boolean) { + nestedActiveMethod(shouldSuspend) + delay(1) + } + + private suspend fun nestedActiveMethod(shouldSuspend: Boolean) { + if (shouldSuspend) delay(1) + notifyTest() + while (coroutineContext[Job]!!.isActive) { + Thread.sleep(100) + } + } + + private suspend fun sleepingOuterMethod() { + sleepingNestedMethod() + delay(1) + } + + private suspend fun sleepingNestedMethod() { + delay(1) + notifyTest() + delay(Long.MAX_VALUE) + } + + private fun awaitCoroutineStarted() { + (monitor as Object).wait() + } + + private fun notifyTest() { + synchronized(monitor) { + (monitor as Object).notify() + } + } +} diff --git a/core/kotlinx-coroutines-debug/test/debug/DebugProbesTest.kt b/core/kotlinx-coroutines-debug/test/debug/DebugProbesTest.kt new file mode 100644 index 0000000000..04c1b05f00 --- /dev/null +++ b/core/kotlinx-coroutines-debug/test/debug/DebugProbesTest.kt @@ -0,0 +1,104 @@ +/* + * Copyright 2016-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license. + */ +package kotlinx.coroutines.debug + +import kotlinx.coroutines.* +import org.junit.Test +import java.util.concurrent.* +import kotlin.test.* + +class DebugProbesTest : TestBase() { + + private fun CoroutineScope.createDeferred(): Deferred<*> = async(NonCancellable) { + throw ExecutionException(null) + } + + @Test + fun testAsync() = runTest { + val deferred = createDeferred() + val traces = listOf( + "java.util.concurrent.ExecutionException\n" + + "\tat kotlinx.coroutines.debug.DebugProbesTest\$createDeferred\$1.invokeSuspend(DebugProbesTest.kt:14)\n" + + "\t(Coroutine boundary)\n" + + "\tat kotlinx.coroutines.DeferredCoroutine.await\$suspendImpl(Builders.common.kt)\n" + + "\tat kotlinx.coroutines.debug.DebugProbesTest.oneMoreNestedMethod(DebugProbesTest.kt:49)\n" + + "\tat kotlinx.coroutines.debug.DebugProbesTest.nestedMethod(DebugProbesTest.kt:44)\n" + + "\tat kotlinx.coroutines.debug.DebugProbesTest\$testAsync\$1.invokeSuspend(DebugProbesTest.kt:17)\n", + "Caused by: java.util.concurrent.ExecutionException\n" + + "\tat kotlinx.coroutines.debug.DebugProbesTest\$createDeferred\$1.invokeSuspend(DebugProbesTest.kt:14)\n" + + "\tat kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:32)" + ) + nestedMethod(deferred, traces) + deferred.join() + } + + @Test + fun testAsyncWithProbes() = DebugProbes.withDebugProbes { + DebugProbes.sanitizeStackTraces = false + runTest { + val deferred = createDeferred() + val traces = listOf( + "java.util.concurrent.ExecutionException\n" + + "\tat kotlinx.coroutines.debug.DebugProbesTest\$createDeferred\$1.invokeSuspend(DebugProbesTest.kt:16)\n" + + "\t(Coroutine boundary)\n" + + "\tat kotlinx.coroutines.DeferredCoroutine.await\$suspendImpl(Builders.common.kt)\n" + + "\tat kotlinx.coroutines.debug.DebugProbesTest.oneMoreNestedMethod(DebugProbesTest.kt:71)\n" + + "\tat kotlinx.coroutines.debug.DebugProbesTest.nestedMethod(DebugProbesTest.kt:66)\n" + + "\tat kotlinx.coroutines.debug.DebugProbesTest\$testAsyncWithProbes\$1\$1.invokeSuspend(DebugProbesTest.kt:43)\n" + + "\t(Coroutine creation stacktrace)\n" + + "\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n" + + "\tat kotlinx.coroutines.intrinsics.CancellableKt.startCoroutineCancellable(Cancellable.kt:23)\n" + + "\tat kotlinx.coroutines.CoroutineStart.invoke(CoroutineStart.kt:99)\n" + + "\tat kotlinx.coroutines.AbstractCoroutine.start(AbstractCoroutine.kt:148)\n" + + "\tat kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:45)\n" + + "\tat kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source)\n" + + "\tat kotlinx.coroutines.TestBase.runTest(TestBase.kt:138)\n" + + "\tat kotlinx.coroutines.TestBase.runTest\$default(TestBase.kt:19)\n" + + "\tat kotlinx.coroutines.debug.DebugProbesTest.testAsyncWithProbes(DebugProbesTest.kt:38)", + "Caused by: java.util.concurrent.ExecutionException\n" + + "\tat kotlinx.coroutines.debug.DebugProbesTest\$createDeferred\$1.invokeSuspend(DebugProbesTest.kt:16)\n" + + "\tat kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:32)\n") + nestedMethod(deferred, traces) + deferred.join() + } + } + + @Test + fun testAsyncWithSanitizedProbes() = DebugProbes.withDebugProbes { + runTest { + val deferred = createDeferred() + val traces = listOf( + "java.util.concurrent.ExecutionException\n" + + "\tat kotlinx.coroutines.debug.DebugProbesTest\$createDeferred\$1.invokeSuspend(DebugProbesTest.kt:16)\n" + + "\t(Coroutine boundary)\n" + + "\tat kotlinx.coroutines.DeferredCoroutine.await\$suspendImpl(Builders.common.kt)\n" + + "\tat kotlinx.coroutines.debug.DebugProbesTest.oneMoreNestedMethod(DebugProbesTest.kt:71)\n" + + "\tat kotlinx.coroutines.debug.DebugProbesTest.nestedMethod(DebugProbesTest.kt:66)\n" + + "\tat kotlinx.coroutines.debug.DebugProbesTest\$testAsyncWithSanitizedProbes\$1\$1.invokeSuspend(DebugProbesTest.kt:43)\n" + + "\t(Coroutine creation stacktrace)\n" + + "\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n" + + "\tat kotlinx.coroutines.intrinsics.CancellableKt.startCoroutineCancellable(Cancellable.kt:23)\n" + + "\tat kotlinx.coroutines.debug.DebugProbesTest.testAsyncWithSanitizedProbes(DebugProbesTest.kt:38)", + "Caused by: java.util.concurrent.ExecutionException\n" + + "\tat kotlinx.coroutines.debug.DebugProbesTest\$createDeferred\$1.invokeSuspend(DebugProbesTest.kt:16)\n" + + "\tat kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:32)\n") + nestedMethod(deferred, traces) + deferred.join() + } + } + + private suspend fun nestedMethod(deferred: Deferred<*>, traces: List) { + oneMoreNestedMethod(deferred, traces) + assertTrue(true) // Prevent tail-call optimization + } + + private suspend fun oneMoreNestedMethod(deferred: Deferred<*>, traces: List) { + try { + deferred.await() + expectUnreached() + } catch (e: ExecutionException) { + verifyStackTrace(e, traces) + } + } +} diff --git a/core/kotlinx-coroutines-debug/test/debug/HierarchyToStringTest.kt b/core/kotlinx-coroutines-debug/test/debug/HierarchyToStringTest.kt new file mode 100644 index 0000000000..a027a54fc0 --- /dev/null +++ b/core/kotlinx-coroutines-debug/test/debug/HierarchyToStringTest.kt @@ -0,0 +1,81 @@ +/* + * Copyright 2016-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license. + */ + +package kotlinx.coroutines.debug + +import kotlinx.coroutines.* +import kotlinx.coroutines.channels.* +import org.junit.* +import org.junit.Test +import kotlin.coroutines.* +import kotlin.test.* + +class HierarchyToStringTest : TestBase() { + + @Before + fun setUp() { + before() + DebugProbes.sanitizeStackTraces = false + DebugProbes.install() + } + + @After + fun tearDown() { + try { + DebugProbes.uninstall() + } finally { + onCompletion() + } + } + + @Test + fun testHierarchy() = runBlocking { + val root = launch { + expect(1) + async(CoroutineName("foo")) { + expect(2) + delay(Long.MAX_VALUE) + } + + actor { + expect(3) + val job = launch { + expect(4) + delay(Long.MAX_VALUE) + } + + withContext(wrapperDispatcher(coroutineContext)) { + expect(5) + job.join() + } + } + } + + repeat(4) { yield() } + expect(6) + val tab = '\t' + val expectedString = """ + Coroutine: "coroutine#2":StandaloneCoroutine{Completing} + $tab"foo#3":DeferredCoroutine{Active}, continuation is SUSPENDED at line kotlinx.coroutines.debug.HierarchyToStringTest${'$'}testHierarchy${'$'}1${'$'}root${'$'}1${'$'}1.invokeSuspend(HierarchyToStringTest.kt:30) + $tab"coroutine#4":ActorCoroutine{Active}, continuation is SUSPENDED at line kotlinx.coroutines.debug.HierarchyToStringTest${'$'}testHierarchy${'$'}1${'$'}root${'$'}1${'$'}2.invokeSuspend(HierarchyToStringTest.kt:40) + $tab$tab"coroutine#5":StandaloneCoroutine{Active}, continuation is SUSPENDED at line kotlinx.coroutines.debug.HierarchyToStringTest${'$'}testHierarchy${'$'}1${'$'}root${'$'}1${'$'}2${'$'}job$1.invokeSuspend(HierarchyToStringTest.kt:37) + $tab$tab"coroutine#4":DispatchedCoroutine{Active}, continuation is SUSPENDED at line kotlinx.coroutines.debug.HierarchyToStringTest${'$'}testHierarchy${'$'}1${'$'}root${'$'}1${'$'}2${'$'}1.invokeSuspend(HierarchyToStringTest.kt:42) + """.trimIndent() + + // DebugProbes.printHierarchy(root) // <- use it for manual validation + assertEquals(expectedString.trimStackTrace(), DebugProbes.hierarchyToString(root).trimEnd().trimStackTrace()) + root.cancel() + root.join() + finish(7) + } + + private fun wrapperDispatcher(context: CoroutineContext): CoroutineContext { + val dispatcher = context[ContinuationInterceptor] as CoroutineDispatcher + return object : CoroutineDispatcher() { + override fun dispatch(context: CoroutineContext, block: Runnable) { + dispatcher.dispatch(context, block) + } + } + } +} diff --git a/core/kotlinx-coroutines-debug/test/debug/SanitizedProbesTest.kt b/core/kotlinx-coroutines-debug/test/debug/SanitizedProbesTest.kt new file mode 100644 index 0000000000..1d44c06993 --- /dev/null +++ b/core/kotlinx-coroutines-debug/test/debug/SanitizedProbesTest.kt @@ -0,0 +1,114 @@ +/* + * Copyright 2016-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license. + */ + +@file:Suppress("PackageDirectoryMismatch") +package definitely.not.kotlinx.coroutines + +import kotlinx.coroutines.* +import kotlinx.coroutines.debug.* +import org.junit.* +import org.junit.Test +import java.io.* +import java.util.concurrent.* +import kotlin.test.* + +class SanitizedProbesTest : TestBase() { + @Before + fun setUp() { + before() + DebugProbes.install() + } + + @After + fun tearDown() { + try { + DebugProbes.uninstall() + } finally { + onCompletion() + } + } + + @Test + fun testRecoveredStackTrace() = runTest { + val deferred = createDeferred() + val traces = listOf( + "java.util.concurrent.ExecutionException\n" + + "\tat definitely.not.kotlinx.coroutines.SanitizedProbesTest\$createDeferredNested\$1.invokeSuspend(SanitizedProbesTest.kt:97)\n" + + "\t(Coroutine boundary)\n" + + "\tat kotlinx.coroutines.DeferredCoroutine.await\$suspendImpl(Builders.common.kt:99)\n" + + "\tat definitely.not.kotlinx.coroutines.SanitizedProbesTest.oneMoreNestedMethod(SanitizedProbesTest.kt:67)\n" + + "\tat definitely.not.kotlinx.coroutines.SanitizedProbesTest.nestedMethod(SanitizedProbesTest.kt:61)\n" + + "\tat definitely.not.kotlinx.coroutines.SanitizedProbesTest\$testRecoveredStackTrace\$1.invokeSuspend(SanitizedProbesTest.kt:50)\n" + + "\t(Coroutine creation stacktrace)\n" + + "\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n" + + "\tat kotlinx.coroutines.intrinsics.CancellableKt.startCoroutineCancellable(Cancellable.kt:23)\n" + + "\tat kotlinx.coroutines.TestBase.runTest\$default(TestBase.kt:141)\n" + + "\tat definitely.not.kotlinx.coroutines.SanitizedProbesTest.testRecoveredStackTrace(SanitizedProbesTest.kt:33)", + "Caused by: java.util.concurrent.ExecutionException\n" + + "\tat definitely.not.kotlinx.coroutines.SanitizedProbesTest\$createDeferredNested\$1.invokeSuspend(SanitizedProbesTest.kt:57)\n" + + "\tat kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:32)\n" + ) + nestedMethod(deferred, traces) + deferred.join() + } + + @Test + fun testCoroutinesDump() = runTest { + val deferred = createActiveDeferred() + yield() + verifyDump( + "Coroutine \"coroutine#3\":BlockingCoroutine{Active}@7d68ef40, state: RUNNING (Last suspension stacktrace, not an actual stacktrace)\n" + + "\tat definitely.not.kotlinx.coroutines.SanitizedProbesTest\$testCoroutinesDump\$1.invokeSuspend(SanitizedProbesTest.kt:58)\n" + + "\t(Coroutine creation stacktrace)\n" + + "\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n" + + "\tat kotlinx.coroutines.intrinsics.CancellableKt.startCoroutineCancellable(Cancellable.kt:23)\n" + + "\tat kotlinx.coroutines.TestBase.runTest\$default(TestBase.kt:141)\n" + + "\tat definitely.not.kotlinx.coroutines.SanitizedProbesTest.testCoroutinesDump(SanitizedProbesTest.kt:56)", + + "Coroutine \"coroutine#4\":DeferredCoroutine{Active}@75c072cb, state: SUSPENDED\n" + + "\tat definitely.not.kotlinx.coroutines.SanitizedProbesTest\$createActiveDeferred\$1.invokeSuspend(SanitizedProbesTest.kt:63)\n" + + "\t(Coroutine creation stacktrace)\n" + + "\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n" + + "\tat kotlinx.coroutines.intrinsics.CancellableKt.startCoroutineCancellable(Cancellable.kt:23)\n" + + "\tat kotlinx.coroutines.BuildersKt.async\$default(Unknown Source)\n" + + "\tat definitely.not.kotlinx.coroutines.SanitizedProbesTest.createActiveDeferred(SanitizedProbesTest.kt:62)\n" + + "\tat definitely.not.kotlinx.coroutines.SanitizedProbesTest.access\$createActiveDeferred(SanitizedProbesTest.kt:16)\n" + + "\tat definitely.not.kotlinx.coroutines.SanitizedProbesTest\$testCoroutinesDump\$1.invokeSuspend(SanitizedProbesTest.kt:57)\n" + + "\tat kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:32)\n" + + "\tat kotlinx.coroutines.DispatchedTask.run(Dispatched.kt:237)\n" + + "\tat kotlinx.coroutines.TestBase.runTest\$default(TestBase.kt:141)\n" + + "\tat definitely.not.kotlinx.coroutines.SanitizedProbesTest.testCoroutinesDump(SanitizedProbesTest.kt:56)" + ) + deferred.cancelAndJoin() + } + + private fun CoroutineScope.createActiveDeferred(): Deferred<*> = async { + suspendingMethod() + assertTrue(true) + } + + private suspend fun suspendingMethod() { + delay(Long.MAX_VALUE) + } + + private fun CoroutineScope.createDeferred(): Deferred<*> = createDeferredNested() + + private fun CoroutineScope.createDeferredNested(): Deferred<*> = async(NonCancellable) { + throw ExecutionException(null) + } + + private suspend fun nestedMethod(deferred: Deferred<*>, traces: List) { + oneMoreNestedMethod(deferred, traces) + assertTrue(true) // Prevent tail-call optimization + } + + private suspend fun oneMoreNestedMethod(deferred: Deferred<*>, traces: List) { + try { + deferred.await() + expectUnreached() + } catch (e: ExecutionException) { + verifyStackTrace(e, traces) + } + } +} \ No newline at end of file diff --git a/core/kotlinx-coroutines-debug/test/debug/StartModeProbesTest.kt b/core/kotlinx-coroutines-debug/test/debug/StartModeProbesTest.kt new file mode 100644 index 0000000000..bd33c5c9d2 --- /dev/null +++ b/core/kotlinx-coroutines-debug/test/debug/StartModeProbesTest.kt @@ -0,0 +1,157 @@ +/* + * Copyright 2016-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license. + */ + +package kotlinx.coroutines.debug + +import kotlinx.coroutines.* +import org.junit.* +import org.junit.Test +import kotlin.test.* + +class StartModeProbesTest : TestBase() { + + @Before + fun setUp() { + before() + DebugProbes.sanitizeStackTraces = false + DebugProbes.install() + } + + @After + fun tearDown() { + try { + DebugProbes.uninstall() + } finally { + onCompletion() + } + } + + @Test + fun testUndispatched() = runTest { + expect(1) + val job = launch(start = CoroutineStart.UNDISPATCHED) { + expect(2) + undispatchedSleeping() + assertTrue(true) + } + + yield() + expect(3) + verifyPartialDump(2, "StartModeProbesTest.undispatchedSleeping") + job.cancelAndJoin() + verifyPartialDump(1, "StartModeProbesTest\$testUndispatched") + finish(4) + } + + private suspend fun undispatchedSleeping() { + delay(Long.MAX_VALUE) + assertTrue(true) + } + + @Test + fun testWithTimeoutWithUndispatched() = runTest { + expect(1) + val job = launchUndispatched() + + yield() + expect(3) + verifyPartialDump( + 2, + "StartModeProbesTest\$launchUndispatched\$1.invokeSuspend", + "StartModeProbesTest.withTimeoutHelper", + "StartModeProbesTest\$withTimeoutHelper\$2.invokeSuspend" + ) + job.cancelAndJoin() + verifyPartialDump(1, "StartModeProbesTest\$testWithTimeoutWithUndispatched") + finish(4) + } + + private fun CoroutineScope.launchUndispatched(): Job { + return launch(start = CoroutineStart.UNDISPATCHED) { + withTimeoutHelper() + assertTrue(true) + } + } + + private suspend fun withTimeoutHelper() { + withTimeout(Long.MAX_VALUE) { + expect(2) + delay(Long.MAX_VALUE) + } + + assertTrue(true) + } + + @Test + fun testWithTimeout() = runTest { + withTimeout(Long.MAX_VALUE) { + testActiveDump( + false, + "StartModeProbesTest\$testWithTimeout\$1.invokeSuspend", + "state: RUNNING" + ) + } + } + + @Test + fun testWithTimeoutAfterYield() = runTest { + withTimeout(Long.MAX_VALUE) { + testActiveDump( + true, + "StartModeProbesTest\$testWithTimeoutAfterYield\$1.invokeSuspend", + "StartModeProbesTest\$testWithTimeoutAfterYield\$1\$1.invokeSuspend", + "StartModeProbesTest.testActiveDump", + "state: RUNNING" + ) + } + } + + private suspend fun testActiveDump(shouldYield: Boolean, vararg expectedFrames: String) { + if (shouldYield) yield() + verifyPartialDump(1, *expectedFrames) + assertTrue(true) + } + + @Test + fun testWithTailCall() = runTest { + expect(1) + val job = tailCallMethod() + yield() + expect(3) + verifyPartialDump(2, "StartModeProbesTest\$launchFromTailCall\$2") + job.cancelAndJoin() + verifyPartialDump(1, "StartModeProbesTest\$testWithTailCall") + finish(4) + } + + private suspend fun CoroutineScope.tailCallMethod(): Job = launchFromTailCall() + private suspend fun CoroutineScope.launchFromTailCall(): Job = launch { + expect(2) + delay(Long.MAX_VALUE) + } + + @Test + fun testCoroutineScope() = runTest { + expect(1) + val job = launch(start = CoroutineStart.UNDISPATCHED) { + runScope() + } + + yield() + expect(3) + verifyPartialDump( + 2, + "StartModeProbesTest\$runScope\$2.invokeSuspend", + "StartModeProbesTest\$testCoroutineScope\$1\$job\$1.invokeSuspend") + job.cancelAndJoin() + finish(4) + } + + private suspend fun runScope() { + coroutineScope { + expect(2) + delay(Long.MAX_VALUE) + } + } +} diff --git a/core/kotlinx-coroutines-debug/test/debug/StracktraceUtils.kt b/core/kotlinx-coroutines-debug/test/debug/StracktraceUtils.kt new file mode 100644 index 0000000000..c85b3cd7e9 --- /dev/null +++ b/core/kotlinx-coroutines-debug/test/debug/StracktraceUtils.kt @@ -0,0 +1,101 @@ +/* + * Copyright 2016-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license. + */ + +package kotlinx.coroutines.debug + +import java.io.* +import kotlin.test.* + +public fun String.trimStackTrace(): String { + return trimIndent().replace(Regex(":[0-9]+"), "").applyBackspace() +} + +public fun String.applyBackspace(): String { + val array = toCharArray() + val stack = CharArray(array.size) + var stackSize = -1 + for (c in array) { + if (c != '\b') { + stack[++stackSize] = c + } else { + --stackSize + } + } + + return String(stack, 0, stackSize + 1) +} + +public fun verifyStackTrace(e: Throwable, traces: List) { + val stacktrace = toStackTrace(e) + traces.forEach { + val expectedLines = it.trimStackTrace().split("\n") + for (i in 0 until expectedLines.size) { + traces.forEach { + assertTrue( + stacktrace.trimStackTrace().contains(it.trimStackTrace()), + "\nExpected trace element:\n$it\n\nActual stacktrace:\n$stacktrace" + ) + } + } + } + + val causes = stacktrace.count("Caused by") + assertNotEquals(0, causes) + assertEquals(causes, traces.map { it.count("Caused by") }.sum()) +} + +public fun toStackTrace(t: Throwable): String { + val sw = StringWriter() as Writer + t.printStackTrace(PrintWriter(sw)) + return sw.toString() +} + +public fun String.count(substring: String): Int = split(substring).size - 1 + +public fun verifyDump(vararg traces: String) { + val baos = ByteArrayOutputStream() + DebugProbes.dumpCoroutines(PrintStream(baos)) + val trace = baos.toString().split("\n\n") + if (traces.isEmpty()) { + assertEquals(1, trace.size) + assertTrue(trace[0].startsWith("Coroutines dump")) + return + } + + trace.withIndex().drop(1).forEach { (index, value) -> + val expected = traces[index - 1].applyBackspace().split("\n\t(Coroutine creation stacktrace)\n", limit = 2) + val actual = value.applyBackspace().split("\n\t(Coroutine creation stacktrace)\n", limit = 2) + assertEquals(expected.size, actual.size) + + expected.withIndex().forEach { (index, trace) -> + val actualTrace = actual[index].trimStackTrace().sanitizeAddresses() + val expectedTrace = trace.trimStackTrace().sanitizeAddresses() + val actualLines = actualTrace.split("\n") + val expectedLines = expectedTrace.split("\n") + for (i in 0 until expectedLines.size) { + assertEquals(expectedLines[i], actualLines[i]) + } + } + } +} + +public fun verifyPartialDump(createdCoroutinesCount: Int, vararg frames: String) { + val baos = ByteArrayOutputStream() + DebugProbes.dumpCoroutines(PrintStream(baos)) + val dump = baos.toString() + val trace = dump.split("\n\n") + val matches = frames.all { frame -> + trace.any { tr -> tr.contains(frame) } + } + + assertEquals(createdCoroutinesCount, DebugProbes.dumpCoroutinesState().size) + assertTrue(matches) +} + +private fun String.sanitizeAddresses(): String { + val index = indexOf("coroutine#") + val next = indexOf(',', index) + if (index == -1 || next == -1) return this + return substring(0, index) + substring(next, length) +} diff --git a/gradle.properties b/gradle.properties index df587f53ea..51834fa113 100644 --- a/gradle.properties +++ b/gradle.properties @@ -11,6 +11,7 @@ html_version=0.6.8 lincheck_version=1.9 dokka_version=0.9.16-rdev-2-mpp-hacks bintray_version=1.8.2-SNAPSHOT +byte_buddy_version=1.9.3 artifactory_plugin_version=4.7.3 # JS diff --git a/js/kotlinx-coroutines-core-js/src/internal/ProbesSupport.kt b/js/kotlinx-coroutines-core-js/src/internal/ProbesSupport.kt new file mode 100644 index 0000000000..81b6476bc2 --- /dev/null +++ b/js/kotlinx-coroutines-core-js/src/internal/ProbesSupport.kt @@ -0,0 +1,10 @@ +/* + * Copyright 2016-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license. + */ + +package kotlinx.coroutines.internal + +import kotlin.coroutines.* + +@Suppress("NOTHING_TO_INLINE") +internal actual inline fun probeCoroutineCreated(completion: Continuation): Continuation = completion diff --git a/knit/resources/knit.properties b/knit/resources/knit.properties index aa639bd36e..4384efd47d 100644 --- a/knit/resources/knit.properties +++ b/knit/resources/knit.properties @@ -4,6 +4,6 @@ site.root=https://kotlin.github.io/kotlinx.coroutines -module.roots=common js core integration native reactive ui +module.roots=common js core debug integration native reactive ui module.marker=build.gradle module.docs=build/dokka diff --git a/native/kotlinx-coroutines-core-native/src/internal/ProbesSupport.kt b/native/kotlinx-coroutines-core-native/src/internal/ProbesSupport.kt new file mode 100644 index 0000000000..c2daab50b7 --- /dev/null +++ b/native/kotlinx-coroutines-core-native/src/internal/ProbesSupport.kt @@ -0,0 +1,10 @@ +/* + * Copyright 2016-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license. + */ + +package kotlinx.coroutines.internal + +import kotlin.coroutines.* + +@Suppress("NOTHING_TO_INLINE") +internal actual inline fun probeCoroutineCreated(completion: Continuation): Continuation = completion \ No newline at end of file diff --git a/settings.gradle b/settings.gradle index 449f7cb2d9..46f3bb598c 100644 --- a/settings.gradle +++ b/settings.gradle @@ -23,6 +23,7 @@ module('binary-compatibility-validator') module('common/kotlinx-coroutines-core-common') module('core/kotlinx-coroutines-core') +module('core/kotlinx-coroutines-debug') module('core/stdlib-stubs') module('integration/kotlinx-coroutines-guava') From 8e2428c591dad7da8c8d003aa928884e5c7771e5 Mon Sep 17 00:00:00 2001 From: Vsevolod Tolstopyatov Date: Mon, 10 Dec 2018 19:12:08 +0300 Subject: [PATCH 2/7] Merge scoped coroutines into one in agent representation to avoid misleading dumps --- .../src/internal/StackTraceRecovery.kt | 6 ++ core/kotlinx-coroutines-debug/README.md | 2 + core/kotlinx-coroutines-debug/build.gradle | 3 - .../src/debug/AgentPremain.kt | 5 +- .../src/debug/CoroutineState.kt | 10 +-- .../src/debug/DebugProbes.kt | 4 +- .../src/debug/internal/DebugProbesImpl.kt | 30 +++++---- .../test/debug/CoroutinesDumpTest.kt | 30 ++++----- .../test/debug/HierarchyToStringTest.kt | 62 ++++++++++++------ .../test/debug/SanitizedProbesTest.kt | 4 +- .../test/debug/ScopedBuildersTest.kt | 64 +++++++++++++++++++ .../test/debug/StracktraceUtils.kt | 8 ++- 12 files changed, 166 insertions(+), 62 deletions(-) create mode 100644 core/kotlinx-coroutines-debug/test/debug/ScopedBuildersTest.kt diff --git a/core/kotlinx-coroutines-core/src/internal/StackTraceRecovery.kt b/core/kotlinx-coroutines-core/src/internal/StackTraceRecovery.kt index 0b3181f302..4c79dcc94e 100644 --- a/core/kotlinx-coroutines-core/src/internal/StackTraceRecovery.kt +++ b/core/kotlinx-coroutines-core/src/internal/StackTraceRecovery.kt @@ -179,6 +179,9 @@ private fun createStackTrace(continuation: CoroutineStackFrame): ArrayDeque, public val creationStackTrace: List, - internal val sequenceNumber: Long) { + @JvmField internal val sequenceNumber: Long +) { /** * [Job] associated with a current coroutine or [IllegalStateException] otherwise. @@ -37,7 +38,8 @@ public data class CoroutineState internal constructor( public val state: State get() = _state // Copy constructor - internal constructor(coroutine: Continuation<*>, state: CoroutineState) : this(coroutine, + internal constructor(coroutine: Continuation<*>, state: CoroutineState) : this( + coroutine, state.creationStackTrace, state.sequenceNumber) { _state = state.state @@ -49,9 +51,7 @@ public data class CoroutineState internal constructor( private var lastObservedFrame: CoroutineStackFrame? = null internal fun updateState(state: State, frame: Continuation<*>) { - if (_state == state && lastObservedFrame != null) { - return - } + if (_state == state && lastObservedFrame != null) return _state = state lastObservedFrame = frame as? CoroutineStackFrame diff --git a/core/kotlinx-coroutines-debug/src/debug/DebugProbes.kt b/core/kotlinx-coroutines-debug/src/debug/DebugProbes.kt index 168c6072d4..0f2c489797 100644 --- a/core/kotlinx-coroutines-debug/src/debug/DebugProbes.kt +++ b/core/kotlinx-coroutines-debug/src/debug/DebugProbes.kt @@ -27,8 +27,8 @@ import kotlin.coroutines.* * * `probeCoroutineCreated` is invoked on every coroutine creation using stdlib intrinsics. * * Overhead: - * * Every created continuation is stored in a weak hash map, thus adding additional GC pressure. - * * On every created continuation, stacktrace of the current thread is dumped. + * * Every created coroutine is stored in a weak hash map, thus adding additional GC pressure. + * * On every created coroutine, stacktrace of the current thread is dumped. * * On every `resume` and `suspend`, [WeakHashMap] is updated under a global lock. * * **WARNING: DO NOT USE DEBUG PROBES IN PRODUCTION ENVIRONMENT.** diff --git a/core/kotlinx-coroutines-debug/src/debug/internal/DebugProbesImpl.kt b/core/kotlinx-coroutines-debug/src/debug/internal/DebugProbesImpl.kt index 7f3be13f1b..a4484f58de 100644 --- a/core/kotlinx-coroutines-debug/src/debug/internal/DebugProbesImpl.kt +++ b/core/kotlinx-coroutines-debug/src/debug/internal/DebugProbesImpl.kt @@ -84,7 +84,10 @@ internal object DebugProbesImpl { @Suppress("DEPRECATION_ERROR") val str = if (this !is JobSupport) toString() else toDebugString() if (state == null) { - builder.append("Coroutine: $str\n") + @Suppress("INVISIBLE_REFERENCE") + if (this !is ScopeCoroutine<*>) { // Do not print scoped coroutines + builder.append("$str\n") + } } else { val element = state.lastObservedStackTrace().firstOrNull() val contState = state.state @@ -169,14 +172,9 @@ internal object DebugProbesImpl { coroutineState.updateState(state, frame) } - private fun Continuation<*>.owner(): ArtificialStackFrame<*>? { - var frame = this as? CoroutineStackFrame ?: return null - while (true) { - if (frame is ArtificialStackFrame<*>) return frame - val completion = frame.callerFrame ?: return null - frame = completion - } - } + private fun Continuation<*>.owner(): ArtificialStackFrame<*>? = (this as? CoroutineStackFrame)?.owner() + + private tailrec fun CoroutineStackFrame.owner(): ArtificialStackFrame<*>? = if (this is ArtificialStackFrame<*>) this else callerFrame?.owner() @Synchronized internal fun probeCoroutineCreated(completion: Continuation): Continuation { @@ -184,6 +182,15 @@ internal object DebugProbesImpl { return completion } + /* + * If completion already has an owner, it means that we are in scoped coroutine (coroutineScope, withContext etc.), + * then piggyback on its already existing owner and do not replace completion + */ + val owner = completion.owner() + if (owner != null) { + return completion + } + /* * Here we replace completion with a sequence of CoroutineStackFrame objects * which represents creation stacktrace, thus making stacktrace recovery mechanism @@ -211,8 +218,9 @@ internal object DebugProbesImpl { capturedCoroutines.remove(coroutine) } - private class ArtificialStackFrame(val delegate: Continuation, frame: CoroutineStackFrame) : - Continuation by delegate, CoroutineStackFrame by frame { + private class ArtificialStackFrame( + @JvmField val delegate: Continuation, + frame: CoroutineStackFrame) : Continuation by delegate, CoroutineStackFrame by frame { override fun resumeWith(result: Result) { probeCoroutineCompleted(this) diff --git a/core/kotlinx-coroutines-debug/test/debug/CoroutinesDumpTest.kt b/core/kotlinx-coroutines-debug/test/debug/CoroutinesDumpTest.kt index 0b97a679c3..870036896e 100644 --- a/core/kotlinx-coroutines-debug/test/debug/CoroutinesDumpTest.kt +++ b/core/kotlinx-coroutines-debug/test/debug/CoroutinesDumpTest.kt @@ -7,7 +7,6 @@ package kotlinx.coroutines.debug import kotlinx.coroutines.* import org.junit.* import org.junit.Test -import java.io.* import kotlin.coroutines.* import kotlin.test.* @@ -88,20 +87,21 @@ class CoroutinesDumpTest : TestBase() { awaitCoroutineStarted() verifyDump( - "Coroutine \"coroutine#1\":DeferredCoroutine{Active}@1e4a7dd4, state: RUNNING (Last suspension stacktrace, not an actual stacktrace)\n" + - "\tat kotlinx.coroutines.debug.CoroutinesDumpTest.nestedActiveMethod(CoroutinesDumpTest.kt:111)\n" + - "\tat kotlinx.coroutines.debug.CoroutinesDumpTest.activeMethod(CoroutinesDumpTest.kt:106)\n" + - "\tat kotlinx.coroutines.debug.CoroutinesDumpTest\$testRunningCoroutineWithSuspensionPoint\$1\$deferred\$1.invokeSuspend(CoroutinesDumpTest.kt:71)\n" + - "\t(Coroutine creation stacktrace)\n" + - "\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n" + - "\tat kotlinx.coroutines.intrinsics.CancellableKt.startCoroutineCancellable(Cancellable.kt:23)\n" + - "\tat kotlinx.coroutines.CoroutineStart.invoke(CoroutineStart.kt:99)\n" + - "\tat kotlinx.coroutines.AbstractCoroutine.start(AbstractCoroutine.kt:148)\n" + - "\tat kotlinx.coroutines.BuildersKt__Builders_commonKt.async(Builders.common.kt)\n" + - "\tat kotlinx.coroutines.BuildersKt.async(Unknown Source)\n" + - "\tat kotlinx.coroutines.BuildersKt__Builders_commonKt.async\$default(Builders.common.kt)\n" + - "\tat kotlinx.coroutines.BuildersKt.async\$default(Unknown Source)\n" + - "\tat kotlinx.coroutines.debug.CoroutinesDumpTest.testRunningCoroutineWithSuspensionPoint(CoroutinesDumpTest.kt:71)") + "Coroutine \"coroutine#1\":DeferredCoroutine{Active}@1e4a7dd4, state: RUNNING (Last suspension stacktrace, not an actual stacktrace)\n" + + "\tat kotlinx.coroutines.debug.CoroutinesDumpTest.nestedActiveMethod(CoroutinesDumpTest.kt:111)\n" + + "\tat kotlinx.coroutines.debug.CoroutinesDumpTest.activeMethod(CoroutinesDumpTest.kt:106)\n" + + "\tat kotlinx.coroutines.debug.CoroutinesDumpTest\$testRunningCoroutineWithSuspensionPoint\$1\$deferred\$1.invokeSuspend(CoroutinesDumpTest.kt:71)\n" + + "\t(Coroutine creation stacktrace)\n" + + "\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n" + + "\tat kotlinx.coroutines.intrinsics.CancellableKt.startCoroutineCancellable(Cancellable.kt:23)\n" + + "\tat kotlinx.coroutines.CoroutineStart.invoke(CoroutineStart.kt:99)\n" + + "\tat kotlinx.coroutines.AbstractCoroutine.start(AbstractCoroutine.kt:148)\n" + + "\tat kotlinx.coroutines.BuildersKt__Builders_commonKt.async(Builders.common.kt)\n" + + "\tat kotlinx.coroutines.BuildersKt.async(Unknown Source)\n" + + "\tat kotlinx.coroutines.BuildersKt__Builders_commonKt.async\$default(Builders.common.kt)\n" + + "\tat kotlinx.coroutines.BuildersKt.async\$default(Unknown Source)\n" + + "\tat kotlinx.coroutines.debug.CoroutinesDumpTest.testRunningCoroutineWithSuspensionPoint(CoroutinesDumpTest.kt:71)" + ) deferred.cancel() runBlocking { deferred.join() } } diff --git a/core/kotlinx-coroutines-debug/test/debug/HierarchyToStringTest.kt b/core/kotlinx-coroutines-debug/test/debug/HierarchyToStringTest.kt index a027a54fc0..6a6b4feda5 100644 --- a/core/kotlinx-coroutines-debug/test/debug/HierarchyToStringTest.kt +++ b/core/kotlinx-coroutines-debug/test/debug/HierarchyToStringTest.kt @@ -30,8 +30,45 @@ class HierarchyToStringTest : TestBase() { } @Test - fun testHierarchy() = runBlocking { - val root = launch { + fun testCompletingHierarchy() = runBlocking { + val tab = '\t' + val expectedString = """ + "coroutine#2":StandaloneCoroutine{Completing} + $tab"foo#3":DeferredCoroutine{Active}, continuation is SUSPENDED at line HierarchyToStringTest${'$'}launchHierarchy${'$'}1${'$'}1.invokeSuspend(HierarchyToStringTest.kt:30) + $tab"coroutine#4":ActorCoroutine{Active}, continuation is SUSPENDED at line HierarchyToStringTest${'$'}launchHierarchy${'$'}1${'$'}2${'$'}1.invokeSuspend(HierarchyToStringTest.kt:40) + $tab$tab"coroutine#5":StandaloneCoroutine{Active}, continuation is SUSPENDED at line HierarchyToStringTest${'$'}launchHierarchy${'$'}1${'$'}2${'$'}job$1.invokeSuspend(HierarchyToStringTest.kt:37) + """.trimIndent() + + checkHierarchy(isCompleting = true, expectedString = expectedString) + } + + @Test + fun testActiveHierarchy() = runBlocking { + val tab = '\t' + val expectedString = """ + "coroutine#2":StandaloneCoroutine{Active}, continuation is SUSPENDED at line HierarchyToStringTest${'$'}launchHierarchy${'$'}1.invokeSuspend(HierarchyToStringTest.kt:94) + $tab"foo#3":DeferredCoroutine{Active}, continuation is SUSPENDED at line HierarchyToStringTest${'$'}launchHierarchy${'$'}1${'$'}1.invokeSuspend(HierarchyToStringTest.kt:30) + $tab"coroutine#4":ActorCoroutine{Active}, continuation is SUSPENDED at line HierarchyToStringTest${'$'}launchHierarchy${'$'}1${'$'}2${'$'}1.invokeSuspend(HierarchyToStringTest.kt:40) + $tab$tab"coroutine#5":StandaloneCoroutine{Active}, continuation is SUSPENDED at line HierarchyToStringTest${'$'}launchHierarchy${'$'}1${'$'}2${'$'}job$1.invokeSuspend(HierarchyToStringTest.kt:37) + """.trimIndent() + checkHierarchy(isCompleting = false, expectedString = expectedString) + } + + private suspend fun CoroutineScope.checkHierarchy(isCompleting: Boolean, expectedString: String) { + val root = launchHierarchy(isCompleting) + repeat(4) { yield() } + expect(6) + assertEquals( + expectedString.trimStackTrace().trimPackage(), + DebugProbes.hierarchyToString(root).trimEnd().trimStackTrace().trimPackage() + ) + root.cancel() + root.join() + finish(7) + } + + private fun CoroutineScope.launchHierarchy(isCompleting: Boolean): Job { + return launch { expect(1) async(CoroutineName("foo")) { expect(2) @@ -50,24 +87,11 @@ class HierarchyToStringTest : TestBase() { job.join() } } - } - - repeat(4) { yield() } - expect(6) - val tab = '\t' - val expectedString = """ - Coroutine: "coroutine#2":StandaloneCoroutine{Completing} - $tab"foo#3":DeferredCoroutine{Active}, continuation is SUSPENDED at line kotlinx.coroutines.debug.HierarchyToStringTest${'$'}testHierarchy${'$'}1${'$'}root${'$'}1${'$'}1.invokeSuspend(HierarchyToStringTest.kt:30) - $tab"coroutine#4":ActorCoroutine{Active}, continuation is SUSPENDED at line kotlinx.coroutines.debug.HierarchyToStringTest${'$'}testHierarchy${'$'}1${'$'}root${'$'}1${'$'}2.invokeSuspend(HierarchyToStringTest.kt:40) - $tab$tab"coroutine#5":StandaloneCoroutine{Active}, continuation is SUSPENDED at line kotlinx.coroutines.debug.HierarchyToStringTest${'$'}testHierarchy${'$'}1${'$'}root${'$'}1${'$'}2${'$'}job$1.invokeSuspend(HierarchyToStringTest.kt:37) - $tab$tab"coroutine#4":DispatchedCoroutine{Active}, continuation is SUSPENDED at line kotlinx.coroutines.debug.HierarchyToStringTest${'$'}testHierarchy${'$'}1${'$'}root${'$'}1${'$'}2${'$'}1.invokeSuspend(HierarchyToStringTest.kt:42) - """.trimIndent() - // DebugProbes.printHierarchy(root) // <- use it for manual validation - assertEquals(expectedString.trimStackTrace(), DebugProbes.hierarchyToString(root).trimEnd().trimStackTrace()) - root.cancel() - root.join() - finish(7) + if (!isCompleting) { + delay(Long.MAX_VALUE) + } + } } private fun wrapperDispatcher(context: CoroutineContext): CoroutineContext { diff --git a/core/kotlinx-coroutines-debug/test/debug/SanitizedProbesTest.kt b/core/kotlinx-coroutines-debug/test/debug/SanitizedProbesTest.kt index 1d44c06993..925f2f7219 100644 --- a/core/kotlinx-coroutines-debug/test/debug/SanitizedProbesTest.kt +++ b/core/kotlinx-coroutines-debug/test/debug/SanitizedProbesTest.kt @@ -9,7 +9,6 @@ import kotlinx.coroutines.* import kotlinx.coroutines.debug.* import org.junit.* import org.junit.Test -import java.io.* import java.util.concurrent.* import kotlin.test.* @@ -17,6 +16,7 @@ class SanitizedProbesTest : TestBase() { @Before fun setUp() { before() + DebugProbes.sanitizeStackTraces = true DebugProbes.install() } @@ -111,4 +111,4 @@ class SanitizedProbesTest : TestBase() { verifyStackTrace(e, traces) } } -} \ No newline at end of file +} diff --git a/core/kotlinx-coroutines-debug/test/debug/ScopedBuildersTest.kt b/core/kotlinx-coroutines-debug/test/debug/ScopedBuildersTest.kt new file mode 100644 index 0000000000..d0657d7a5b --- /dev/null +++ b/core/kotlinx-coroutines-debug/test/debug/ScopedBuildersTest.kt @@ -0,0 +1,64 @@ +/* + * Copyright 2016-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license. + */ + +package kotlinx.coroutines.debug + +import kotlinx.coroutines.* +import org.junit.* +import kotlin.coroutines.* + +class ScopedBuildersTest : TestBase() { + @Before + fun setUp() { + before() + DebugProbes.sanitizeStackTraces = false + DebugProbes.install() + } + + @After + fun tearDown() { + try { + DebugProbes.uninstall() + } finally { + onCompletion() + } + } + + @Test + fun testNestedScopes() = runBlocking { + val job = launch { doInScope() } + yield() + yield() + verifyDump( + "Coroutine \"coroutine#1\":BlockingCoroutine{Active}@16612a51, state: RUNNING (Last suspension stacktrace, not an actual stacktrace)\n" + + "\tat kotlinx.coroutines.debug.ScopedBuildersTest\$testNestedScopes\$1.invokeSuspend(ScopedBuildersTest.kt:32)\n" + + "\t(Coroutine creation stacktrace)\n" + + "\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n", + + "Coroutine \"coroutine#2\":StandaloneCoroutine{Active}@6b53e23f, state: SUSPENDED\n" + + "\tat kotlinx.coroutines.debug.ScopedBuildersTest\$doWithContext\$2.invokeSuspend(ScopedBuildersTest.kt:49)\n" + + "\tat kotlinx.coroutines.debug.ScopedBuildersTest.doWithContext(ScopedBuildersTest.kt:47)\n" + + "\tat kotlinx.coroutines.debug.ScopedBuildersTest\$doInScope\$2.invokeSuspend(ScopedBuildersTest.kt:41)\n" + + "\tat kotlinx.coroutines.debug.ScopedBuildersTest\$testNestedScopes\$1\$job\$1.invokeSuspend(ScopedBuildersTest.kt:30)\n" + + "\t(Coroutine creation stacktrace)\n" + + "\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)") + job.cancelAndJoin() + finish(4) + } + + private suspend fun doInScope() = coroutineScope { + expect(1) + doWithContext() + expectUnreached() + } + + private suspend fun doWithContext() { + expect(2) + withContext(wrapperDispatcher(coroutineContext)) { + expect(3) + delay(Long.MAX_VALUE) + } + expectUnreached() + } +} \ No newline at end of file diff --git a/core/kotlinx-coroutines-debug/test/debug/StracktraceUtils.kt b/core/kotlinx-coroutines-debug/test/debug/StracktraceUtils.kt index c85b3cd7e9..db89fef835 100644 --- a/core/kotlinx-coroutines-debug/test/debug/StracktraceUtils.kt +++ b/core/kotlinx-coroutines-debug/test/debug/StracktraceUtils.kt @@ -8,7 +8,7 @@ import java.io.* import kotlin.test.* public fun String.trimStackTrace(): String { - return trimIndent().replace(Regex(":[0-9]+"), "").applyBackspace() + return trimIndent().replace(Regex(":[0-9]+"), "").replace(Regex("#[0-9]+"), "").applyBackspace() } public fun String.applyBackspace(): String { @@ -62,7 +62,7 @@ public fun verifyDump(vararg traces: String) { assertTrue(trace[0].startsWith("Coroutines dump")) return } - + // Drop "Coroutine dump" line trace.withIndex().drop(1).forEach { (index, value) -> val expected = traces[index - 1].applyBackspace().split("\n\t(Coroutine creation stacktrace)\n", limit = 2) val actual = value.applyBackspace().split("\n\t(Coroutine creation stacktrace)\n", limit = 2) @@ -80,6 +80,8 @@ public fun verifyDump(vararg traces: String) { } } +public fun String.trimPackage() = replace("kotlinx.coroutines.debug.", "") + public fun verifyPartialDump(createdCoroutinesCount: Int, vararg frames: String) { val baos = ByteArrayOutputStream() DebugProbes.dumpCoroutines(PrintStream(baos)) @@ -94,7 +96,7 @@ public fun verifyPartialDump(createdCoroutinesCount: Int, vararg frames: String) } private fun String.sanitizeAddresses(): String { - val index = indexOf("coroutine#") + val index = indexOf("coroutine\"") val next = indexOf(',', index) if (index == -1 || next == -1) return this return substring(0, index) + substring(next, length) From 5a80d2a0b0c52121a0788acc036030812fea9f59 Mon Sep 17 00:00:00 2001 From: Vsevolod Tolstopyatov Date: Mon, 10 Dec 2018 20:19:35 +0300 Subject: [PATCH 3/7] Debug agent optimizations * Do not store creation stacktrace of the coroutine, recover it from ArtificialStackFrame * Reduce lock window where possible to avoid contention * Avoid stacktrace copying where possible --- .../kotlinx-coroutines-debug.txt | 5 +- .../src/debug/CoroutineState.kt | 27 ++++++- .../src/debug/DebugProbes.kt | 25 +++--- .../src/debug/internal/DebugProbesImpl.kt | 76 ++++++++++--------- .../test/debug/CoroutinesDumpTest.kt | 39 ++++++++-- 5 files changed, 106 insertions(+), 66 deletions(-) diff --git a/binary-compatibility-validator/reference-public-api/kotlinx-coroutines-debug.txt b/binary-compatibility-validator/reference-public-api/kotlinx-coroutines-debug.txt index fa607fbdfa..4f63d7c3e1 100644 --- a/binary-compatibility-validator/reference-public-api/kotlinx-coroutines-debug.txt +++ b/binary-compatibility-validator/reference-public-api/kotlinx-coroutines-debug.txt @@ -1,8 +1,7 @@ public final class kotlinx/coroutines/debug/CoroutineState { public final fun component1 ()Lkotlin/coroutines/Continuation; - public final fun component2 ()Ljava/util/List; - public final fun copy (Lkotlin/coroutines/Continuation;Ljava/util/List;J)Lkotlinx/coroutines/debug/CoroutineState; - public static synthetic fun copy$default (Lkotlinx/coroutines/debug/CoroutineState;Lkotlin/coroutines/Continuation;Ljava/util/List;JILjava/lang/Object;)Lkotlinx/coroutines/debug/CoroutineState; + public final fun copy (Lkotlin/coroutines/Continuation;Lkotlin/coroutines/jvm/internal/CoroutineStackFrame;J)Lkotlinx/coroutines/debug/CoroutineState; + public static synthetic fun copy$default (Lkotlinx/coroutines/debug/CoroutineState;Lkotlin/coroutines/Continuation;Lkotlin/coroutines/jvm/internal/CoroutineStackFrame;JILjava/lang/Object;)Lkotlinx/coroutines/debug/CoroutineState; public fun equals (Ljava/lang/Object;)Z public final fun getContinuation ()Lkotlin/coroutines/Continuation; public final fun getCreationStackTrace ()Ljava/util/List; diff --git a/core/kotlinx-coroutines-debug/src/debug/CoroutineState.kt b/core/kotlinx-coroutines-debug/src/debug/CoroutineState.kt index f6f3e96a23..97e1b6d198 100644 --- a/core/kotlinx-coroutines-debug/src/debug/CoroutineState.kt +++ b/core/kotlinx-coroutines-debug/src/debug/CoroutineState.kt @@ -16,7 +16,7 @@ import kotlin.coroutines.* @ExperimentalCoroutinesApi public data class CoroutineState internal constructor( public val continuation: Continuation<*>, - public val creationStackTrace: List, + private val creationStackBottom: CoroutineStackFrame, @JvmField internal val sequenceNumber: Long ) { @@ -32,23 +32,42 @@ public data class CoroutineState internal constructor( */ public val jobOrNull: Job? get() = continuation.context[Job] + /** + * Creation stacktrace of coroutine + */ + public val creationStackTrace: List get() = creationStackTrace() + /** * Last observed [state][State] of the coroutine. */ public val state: State get() = _state + private var _state: State = State.CREATED + + private var lastObservedFrame: CoroutineStackFrame? = null + // Copy constructor internal constructor(coroutine: Continuation<*>, state: CoroutineState) : this( coroutine, - state.creationStackTrace, + state.creationStackBottom, state.sequenceNumber) { _state = state.state this.lastObservedFrame = state.lastObservedFrame } - private var _state: State = State.CREATED + private fun creationStackTrace(): List { + // Skip "Coroutine creation stacktrace" frame + return sequence { yieldFrames(creationStackBottom.callerFrame) }.toList() + } - private var lastObservedFrame: CoroutineStackFrame? = null + private tailrec suspend fun SequenceScope.yieldFrames(frame: CoroutineStackFrame?) { + if (frame == null) return + frame.getStackTraceElement()?.let { yield(it) } + val caller = frame.callerFrame + if (caller != null) { + yieldFrames(caller) + } + } internal fun updateState(state: State, frame: Continuation<*>) { if (_state == state && lastObservedFrame != null) return diff --git a/core/kotlinx-coroutines-debug/src/debug/DebugProbes.kt b/core/kotlinx-coroutines-debug/src/debug/DebugProbes.kt index 0f2c489797..12fb9a7957 100644 --- a/core/kotlinx-coroutines-debug/src/debug/DebugProbes.kt +++ b/core/kotlinx-coroutines-debug/src/debug/DebugProbes.kt @@ -16,8 +16,8 @@ import kotlin.coroutines.* /** * Debug probes support. * - * Debug probes is a dynamic attach mechanism, which installs multiple hooks into [Continuation] machinery. - * It slows down all coroutine-related code, but in return provides a lot of debug information, including + * Debug probes is a dynamic attach mechanism which installs multiple hooks into coroutines machinery. + * It slows down all coroutine-related code, but in return provides a lot of diagnostic information, including * asynchronous stack-traces and coroutine dumps (similar to [ThreadMXBean.dumpAllThreads] and `jstack` via [DebugProbes.dumpCoroutines]. * * Installed hooks: @@ -30,8 +30,6 @@ import kotlin.coroutines.* * * Every created coroutine is stored in a weak hash map, thus adding additional GC pressure. * * On every created coroutine, stacktrace of the current thread is dumped. * * On every `resume` and `suspend`, [WeakHashMap] is updated under a global lock. - * - * **WARNING: DO NOT USE DEBUG PROBES IN PRODUCTION ENVIRONMENT.** */ @ExperimentalCoroutinesApi public object DebugProbes { @@ -39,15 +37,13 @@ public object DebugProbes { /** * Whether coroutine creation stacktraces should be sanitized. * Sanitization removes all frames from `kotlinx.coroutines` package except - * the first one and the last one to simplify user's diagnostic. + * the first one and the last one to simplify diagnostic. */ public var sanitizeStackTraces: Boolean = true /** * Installs a [DebugProbes] instead of no-op stdlib probes by redefining * debug probes class using the same class loader as one loaded [DebugProbes] class. - * - * **WARNING: DO NOT USE DEBUG PROBES IN PRODUCTION ENVIRONMENT** */ public fun install() { DebugProbesImpl.install() @@ -62,8 +58,6 @@ public object DebugProbes { /** * Invokes given block of code with installed debug probes and uninstall probes in the end. - * - * **WARNING: DO NOT USE DEBUG PROBES IN PRODUCTION ENVIRONMENT** */ public inline fun withDebugProbes(block: () -> Unit) { install() @@ -81,22 +75,21 @@ public object DebugProbes { public fun hierarchyToString(job: Job): String = DebugProbesImpl.hierarchyToString(job) /** - * Prints [job] hierarchy representation from [hierarchyToString] to given [out]. + * Prints [job] hierarchy representation from [hierarchyToString] to the given [out]. */ public fun printHierarchy(job: Job, out: PrintStream = System.out) = out.println(DebugProbesImpl.hierarchyToString(job)) /** - * Returns all alive coroutine states. - * Resulting collection represents a consistent snapshot of all alive coroutines at the moment of invocation. + * Returns all existing coroutine states. + * The resulting collection represents a consistent snapshot of all existing coroutines at the moment of invocation. */ public fun dumpCoroutinesState(): List = DebugProbesImpl.dumpCoroutinesState() /** - * Dumps all active coroutines into given output stream. - * Resulting collection represents a consistent snapshot of all alive coroutines at the moment of invocation. - * Output of this method is similar to `jstack` or full thread dump, so this method can and should be used as replacement to - * "Dump threads" action + * Dumps all active coroutines into the given output stream, providing a consistent snapshot of all existing coroutines at the moment of invocation. + * The output of this method is similar to `jstack` or a full thread dump. It can be used as the replacement to + * "Dump threads" action. * * Example of the output: * ``` diff --git a/core/kotlinx-coroutines-debug/src/debug/internal/DebugProbesImpl.kt b/core/kotlinx-coroutines-debug/src/debug/internal/DebugProbesImpl.kt index a4484f58de..4d08421880 100644 --- a/core/kotlinx-coroutines-debug/src/debug/internal/DebugProbesImpl.kt +++ b/core/kotlinx-coroutines-debug/src/debug/internal/DebugProbesImpl.kt @@ -25,6 +25,7 @@ internal object DebugProbesImpl { private const val ARTIFICIAL_FRAME_MESSAGE = "Coroutine creation stacktrace" private val dateFormat = SimpleDateFormat("yyyy/MM/dd HH:mm:ss") private val capturedCoroutines = WeakHashMap, CoroutineState>() + @Volatile private var installations = 0 private val isInstalled: Boolean get() = installations > 0 // To sort coroutines by creation order, used as unique id @@ -111,37 +112,39 @@ internal object DebugProbesImpl { .toList() } - @Synchronized public fun dumpCoroutines(out: PrintStream) { if (!isInstalled) { error("Debug probes are not installed") } // Avoid inference with other out/err invocations - val resultingString = buildString { - append("Coroutines dump ${dateFormat.format(System.currentTimeMillis())}") + val resultingString = dumpCoroutines() + out.println(resultingString) + } + @Synchronized + private fun dumpCoroutines(): String { + // Synchronization window can be reduce even more, but no need to do it here + return buildString { + append("Coroutines dump ${dateFormat.format(System.currentTimeMillis())}") capturedCoroutines .asSequence() .sortedBy { it.value.sequenceNumber } .forEach { (key, value) -> - val state = if (value.state == State.RUNNING) - "${value.state} (Last suspension stacktrace, not an actual stacktrace)" - else value.state.toString() - - append("\n\nCoroutine $key, state: $state") - val observedStackTrace = value.lastObservedStackTrace() - if (observedStackTrace.isEmpty()) { - append("\n\tat ${artificialFrame(ARTIFICIAL_FRAME_MESSAGE)}") - printStackTrace(value.creationStackTrace) - } else { - printStackTrace(value.lastObservedStackTrace()) + val state = if (value.state == State.RUNNING) + "${value.state} (Last suspension stacktrace, not an actual stacktrace)" + else value.state.toString() + + append("\n\nCoroutine $key, state: $state") + val observedStackTrace = value.lastObservedStackTrace() + if (observedStackTrace.isEmpty()) { + append("\n\tat ${artificialFrame(ARTIFICIAL_FRAME_MESSAGE)}") + printStackTrace(value.creationStackTrace) + } else { + printStackTrace(value.lastObservedStackTrace()) + } } - } } - - // Move it out of synchronization? - out.println(resultingString) } private fun StringBuilder.printStackTrace(frames: List) { @@ -150,10 +153,8 @@ internal object DebugProbesImpl { } } - @Synchronized internal fun probeCoroutineResumed(frame: Continuation<*>) = updateState(frame, State.RUNNING) - @Synchronized internal fun probeCoroutineSuspended(frame: Continuation<*>) = updateState(frame, State.SUSPENDED) private fun updateState(frame: Continuation<*>, state: State) { @@ -163,6 +164,11 @@ internal object DebugProbesImpl { // Find ArtificialStackFrame of the coroutine val owner = frame.owner() + updateState(owner, frame, state) + } + + @Synchronized + private fun updateState(owner: ArtificialStackFrame<*>?, frame: Continuation<*>, state: State) { val coroutineState = capturedCoroutines[owner] if (coroutineState == null) { warn(frame, state) @@ -176,7 +182,6 @@ internal object DebugProbesImpl { private tailrec fun CoroutineStackFrame.owner(): ArtificialStackFrame<*>? = if (this is ArtificialStackFrame<*>) this else callerFrame?.owner() - @Synchronized internal fun probeCoroutineCreated(completion: Continuation): Continuation { if (!isInstalled) { return completion @@ -197,22 +202,24 @@ internal object DebugProbesImpl { * even more verbose (it will attach coroutine creation stacktrace to all exceptions), * and then using this artificial frame as an identifier of coroutineSuspended/resumed calls. */ - val stacktrace = sanitizedStackTrace(Exception()) - val frames = ArrayList(stacktrace.size) - for ((index, frame) in stacktrace.reversed().withIndex()) { - frames += object : CoroutineStackFrame { - override val callerFrame: CoroutineStackFrame? - get() = if (index == 0) null else frames[index - 1] - + val stacktrace = sanitizeStackTrace(Exception()) + val frame = stacktrace.foldRight(null) { frame, acc -> + object : CoroutineStackFrame { + override val callerFrame: CoroutineStackFrame? = acc override fun getStackTraceElement(): StackTraceElement = frame } - } + }!! - val result = ArtificialStackFrame(completion, frames.last()!!) - capturedCoroutines[result] = CoroutineState(completion, stacktrace.slice(1 until stacktrace.size), ++sequenceNumber) + val result = ArtificialStackFrame(completion, frame) + storeFrame(result, completion) return result } + @Synchronized + private fun storeFrame(frame: ArtificialStackFrame, completion: Continuation) { + capturedCoroutines[frame] = CoroutineState(completion, frame, ++sequenceNumber) + } + @Synchronized private fun probeCoroutineCompleted(coroutine: ArtificialStackFrame<*>) { capturedCoroutines.remove(coroutine) @@ -230,7 +237,7 @@ internal object DebugProbesImpl { override fun toString(): String = delegate.toString() } - private fun sanitizedStackTrace(throwable: T): Array { + private fun sanitizeStackTrace(throwable: T): List { val stackTrace = throwable.stackTrace val size = stackTrace.size @@ -243,7 +250,7 @@ internal object DebugProbesImpl { } if (!DebugProbes.sanitizeStackTraces) { - return Array(size - probeIndex) { + return List(size - probeIndex) { if (it == 0) artificialFrame(ARTIFICIAL_FRAME_MESSAGE) else stackTrace[it + probeIndex] } } @@ -255,7 +262,6 @@ internal object DebugProbesImpl { */ val result = ArrayList(size - probeIndex + 1) result += artificialFrame(ARTIFICIAL_FRAME_MESSAGE) - Thread.sleep(1) var includeInternalFrame = true for (i in (probeIndex + 1) until size - 1) { val element = stackTrace[i] @@ -278,7 +284,7 @@ internal object DebugProbesImpl { } result += stackTrace[size - 1] - return result.toTypedArray() + return result } private val StackTraceElement.isInternalMethod: Boolean get() = className.startsWith("kotlinx.coroutines") diff --git a/core/kotlinx-coroutines-debug/test/debug/CoroutinesDumpTest.kt b/core/kotlinx-coroutines-debug/test/debug/CoroutinesDumpTest.kt index 870036896e..dea77f1af9 100644 --- a/core/kotlinx-coroutines-debug/test/debug/CoroutinesDumpTest.kt +++ b/core/kotlinx-coroutines-debug/test/debug/CoroutinesDumpTest.kt @@ -51,8 +51,7 @@ class CoroutinesDumpTest : TestBase() { val found = DebugProbes.dumpCoroutinesState().single { it.jobOrNull === deferred } assertSame(deferred, found.job) - deferred.cancel() - runBlocking { deferred.join() } + runBlocking { deferred.cancelAndJoin() } } @Test @@ -75,8 +74,7 @@ class CoroutinesDumpTest : TestBase() { "\tat kotlinx.coroutines.BuildersKt__Builders_commonKt.async\$default(Builders.common.kt)\n" + "\tat kotlinx.coroutines.BuildersKt.async\$default(Unknown Source)\n" + "\tat kotlinx.coroutines.debug.CoroutinesDumpTest.testRunningCoroutine(CoroutinesDumpTest.kt:49)") - deferred.cancel() - runBlocking { deferred.join() } + runBlocking { deferred.cancelAndJoin() } } @Test @@ -102,8 +100,34 @@ class CoroutinesDumpTest : TestBase() { "\tat kotlinx.coroutines.BuildersKt.async\$default(Unknown Source)\n" + "\tat kotlinx.coroutines.debug.CoroutinesDumpTest.testRunningCoroutineWithSuspensionPoint(CoroutinesDumpTest.kt:71)" ) - deferred.cancel() - runBlocking { deferred.join() } + runBlocking { deferred.cancelAndJoin() } + } + + @Test + fun testCreationStackTrace() = synchronized(monitor) { + val deferred = GlobalScope.async { + activeMethod(shouldSuspend = true) + } + + awaitCoroutineStarted() + val coroutine = DebugProbes.dumpCoroutinesState().first() + val result = coroutine.creationStackTrace.fold(StringBuilder()) { acc, element -> + acc.append(element.toString()) + acc.append('\n') + }.toString().trimStackTrace() + + runBlocking { deferred.cancelAndJoin() } + + val expected = ("kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n" + + "kotlinx.coroutines.intrinsics.CancellableKt.startCoroutineCancellable(Cancellable.kt:23)\n" + + "kotlinx.coroutines.CoroutineStart.invoke(CoroutineStart.kt:109)\n" + + "kotlinx.coroutines.AbstractCoroutine.start(AbstractCoroutine.kt:160)\n" + + "kotlinx.coroutines.BuildersKt__Builders_commonKt.async(Builders.common.kt:88)\n" + + "kotlinx.coroutines.BuildersKt.async(Unknown Source)\n" + + "kotlinx.coroutines.BuildersKt__Builders_commonKt.async\$default(Builders.common.kt:81)\n" + + "kotlinx.coroutines.BuildersKt.async\$default(Unknown Source)\n" + + "kotlinx.coroutines.debug.CoroutinesDumpTest.testCreationStackTrace(CoroutinesDumpTest.kt:109)").trimStackTrace() + assertTrue(result.startsWith(expected)) } @Test @@ -113,8 +137,7 @@ class CoroutinesDumpTest : TestBase() { } awaitCoroutineStarted() - deferred.cancel() - runBlocking { deferred.join() } + runBlocking { deferred.cancelAndJoin() } verifyDump() } From 12695b763715338149e0bcaa3633a6e0296fc361 Mon Sep 17 00:00:00 2001 From: Roman Elizarov Date: Tue, 11 Dec 2018 19:20:39 +0300 Subject: [PATCH 4/7] Debug agent code style --- .../src/debug/CoroutineState.kt | 4 +- .../src/debug/internal/DebugProbesImpl.kt | 117 +++++++----------- .../test/debug/StracktraceUtils.kt | 10 +- 3 files changed, 51 insertions(+), 80 deletions(-) diff --git a/core/kotlinx-coroutines-debug/src/debug/CoroutineState.kt b/core/kotlinx-coroutines-debug/src/debug/CoroutineState.kt index 97e1b6d198..78f290b8b8 100644 --- a/core/kotlinx-coroutines-debug/src/debug/CoroutineState.kt +++ b/core/kotlinx-coroutines-debug/src/debug/CoroutineState.kt @@ -50,7 +50,8 @@ public data class CoroutineState internal constructor( internal constructor(coroutine: Continuation<*>, state: CoroutineState) : this( coroutine, state.creationStackBottom, - state.sequenceNumber) { + state.sequenceNumber + ) { _state = state.state this.lastObservedFrame = state.lastObservedFrame } @@ -71,7 +72,6 @@ public data class CoroutineState internal constructor( internal fun updateState(state: State, frame: Continuation<*>) { if (_state == state && lastObservedFrame != null) return - _state = state lastObservedFrame = frame as? CoroutineStackFrame } diff --git a/core/kotlinx-coroutines-debug/src/debug/internal/DebugProbesImpl.kt b/core/kotlinx-coroutines-debug/src/debug/internal/DebugProbesImpl.kt index 4d08421880..c40e14ca64 100644 --- a/core/kotlinx-coroutines-debug/src/debug/internal/DebugProbesImpl.kt +++ b/core/kotlinx-coroutines-debug/src/debug/internal/DebugProbesImpl.kt @@ -33,9 +33,7 @@ internal object DebugProbesImpl { @Synchronized public fun install() { - if (++installations > 1) { - return - } + if (++installations > 1) return ByteBuddyAgent.install() val cl = Class.forName("kotlin.coroutines.jvm.internal.DebugProbesKt") @@ -50,7 +48,7 @@ internal object DebugProbesImpl { @Synchronized public fun uninstall() { - if (installations == 0) error("Agent was not installed") + check(isInstalled) { "Agent was not installed" } if (--installations != 0) return capturedCoroutines.clear() @@ -66,17 +64,13 @@ internal object DebugProbesImpl { @Synchronized public fun hierarchyToString(job: Job): String { - if (!isInstalled) { - error("Debug probes are not installed") - } - + check(isInstalled) { "Debug probes are not installed" } val jobToStack = capturedCoroutines .filterKeys { it.delegate.context[Job] != null } .mapKeys { it.key.delegate.context[Job]!! } - - val sb = StringBuilder() - job.build(jobToStack, sb, "") - return sb.toString() + return buildString { + job.build(jobToStack, this, "") + } } private fun Job.build(map: Map, builder: StringBuilder, indent: String) { @@ -94,7 +88,6 @@ internal object DebugProbesImpl { val contState = state.state builder.append("$str, continuation is $contState at line $element\n") } - for (child in children) { child.build(map, builder, indent + "\t") } @@ -102,10 +95,7 @@ internal object DebugProbesImpl { @Synchronized public fun dumpCoroutinesState(): List { - if (!isInstalled) { - error("Debug probes are not installed") - } - + check(isInstalled) { "Debug probes are not installed" } return capturedCoroutines.entries.asSequence() .map { CoroutineState(it.key.delegate, it.value) } .sortedBy { it.sequenceNumber } @@ -113,38 +103,33 @@ internal object DebugProbesImpl { } public fun dumpCoroutines(out: PrintStream) { - if (!isInstalled) { - error("Debug probes are not installed") - } - - // Avoid inference with other out/err invocations - val resultingString = dumpCoroutines() - out.println(resultingString) + check(isInstalled) { "Debug probes are not installed" } + // Avoid inference with other out/err invocations by creating a string first + dumpCoroutines().let { out.println(it) } } @Synchronized - private fun dumpCoroutines(): String { + private fun dumpCoroutines(): String = buildString { // Synchronization window can be reduce even more, but no need to do it here - return buildString { - append("Coroutines dump ${dateFormat.format(System.currentTimeMillis())}") - capturedCoroutines - .asSequence() - .sortedBy { it.value.sequenceNumber } - .forEach { (key, value) -> - val state = if (value.state == State.RUNNING) - "${value.state} (Last suspension stacktrace, not an actual stacktrace)" - else value.state.toString() - - append("\n\nCoroutine $key, state: $state") - val observedStackTrace = value.lastObservedStackTrace() - if (observedStackTrace.isEmpty()) { - append("\n\tat ${artificialFrame(ARTIFICIAL_FRAME_MESSAGE)}") - printStackTrace(value.creationStackTrace) - } else { - printStackTrace(value.lastObservedStackTrace()) - } + append("Coroutines dump ${dateFormat.format(System.currentTimeMillis())}") + capturedCoroutines + .asSequence() + .sortedBy { it.value.sequenceNumber } + .forEach { (key, value) -> + val state = if (value.state == State.RUNNING) + "${value.state} (Last suspension stacktrace, not an actual stacktrace)" + else + value.state.toString() + + append("\n\nCoroutine $key, state: $state") + val observedStackTrace = value.lastObservedStackTrace() + if (observedStackTrace.isEmpty()) { + append("\n\tat ${artificialFrame(ARTIFICIAL_FRAME_MESSAGE)}") + printStackTrace(value.creationStackTrace) + } else { + printStackTrace(value.lastObservedStackTrace()) } - } + } } private fun StringBuilder.printStackTrace(frames: List) { @@ -158,10 +143,7 @@ internal object DebugProbesImpl { internal fun probeCoroutineSuspended(frame: Continuation<*>) = updateState(frame, State.SUSPENDED) private fun updateState(frame: Continuation<*>, state: State) { - if (!isInstalled) { - return - } - + if (!isInstalled) return // Find ArtificialStackFrame of the coroutine val owner = frame.owner() updateState(owner, frame, state) @@ -174,28 +156,23 @@ internal object DebugProbesImpl { warn(frame, state) return } - coroutineState.updateState(state, frame) } - private fun Continuation<*>.owner(): ArtificialStackFrame<*>? = (this as? CoroutineStackFrame)?.owner() + private fun Continuation<*>.owner(): ArtificialStackFrame<*>? = + (this as? CoroutineStackFrame)?.owner() - private tailrec fun CoroutineStackFrame.owner(): ArtificialStackFrame<*>? = if (this is ArtificialStackFrame<*>) this else callerFrame?.owner() + private tailrec fun CoroutineStackFrame.owner(): ArtificialStackFrame<*>? = + if (this is ArtificialStackFrame<*>) this else callerFrame?.owner() internal fun probeCoroutineCreated(completion: Continuation): Continuation { - if (!isInstalled) { - return completion - } - + if (!isInstalled) return completion /* * If completion already has an owner, it means that we are in scoped coroutine (coroutineScope, withContext etc.), * then piggyback on its already existing owner and do not replace completion */ val owner = completion.owner() - if (owner != null) { - return completion - } - + if (owner != null) return completion /* * Here we replace completion with a sequence of CoroutineStackFrame objects * which represents creation stacktrace, thus making stacktrace recovery mechanism @@ -208,11 +185,10 @@ internal object DebugProbesImpl { override val callerFrame: CoroutineStackFrame? = acc override fun getStackTraceElement(): StackTraceElement = frame } - }!! - - val result = ArtificialStackFrame(completion, frame) - storeFrame(result, completion) - return result + } + return ArtificialStackFrame(completion, frame!!).also { + storeFrame(it, completion) + } } @Synchronized @@ -227,8 +203,8 @@ internal object DebugProbesImpl { private class ArtificialStackFrame( @JvmField val delegate: Continuation, - frame: CoroutineStackFrame) : Continuation by delegate, CoroutineStackFrame by frame { - + frame: CoroutineStackFrame + ) : Continuation by delegate, CoroutineStackFrame by frame { override fun resumeWith(result: Result) { probeCoroutineCompleted(this) delegate.resumeWith(result) @@ -240,14 +216,7 @@ internal object DebugProbesImpl { private fun sanitizeStackTrace(throwable: T): List { val stackTrace = throwable.stackTrace val size = stackTrace.size - - var probeIndex = -1 - for (i in 0 until size) { - val name = stackTrace[i].className - if ("kotlin.coroutines.jvm.internal.DebugProbesKt" == name) { - probeIndex = i - } - } + val probeIndex = stackTrace.indexOfLast { it.className == "kotlin.coroutines.jvm.internal.DebugProbesKt" } if (!DebugProbes.sanitizeStackTraces) { return List(size - probeIndex) { diff --git a/core/kotlinx-coroutines-debug/test/debug/StracktraceUtils.kt b/core/kotlinx-coroutines-debug/test/debug/StracktraceUtils.kt index db89fef835..baa48b038d 100644 --- a/core/kotlinx-coroutines-debug/test/debug/StracktraceUtils.kt +++ b/core/kotlinx-coroutines-debug/test/debug/StracktraceUtils.kt @@ -7,9 +7,11 @@ package kotlinx.coroutines.debug import java.io.* import kotlin.test.* -public fun String.trimStackTrace(): String { - return trimIndent().replace(Regex(":[0-9]+"), "").replace(Regex("#[0-9]+"), "").applyBackspace() -} +public fun String.trimStackTrace(): String = + trimIndent() + .replace(Regex(":[0-9]+"), "") + .replace(Regex("#[0-9]+"), "") + .applyBackspace() public fun String.applyBackspace(): String { val array = toCharArray() @@ -46,7 +48,7 @@ public fun verifyStackTrace(e: Throwable, traces: List) { } public fun toStackTrace(t: Throwable): String { - val sw = StringWriter() as Writer + val sw = StringWriter() t.printStackTrace(PrintWriter(sw)) return sw.toString() } From 7520c978464e2f3b1cc075dea36a9f11088e2d85 Mon Sep 17 00:00:00 2001 From: Vsevolod Tolstopyatov Date: Tue, 11 Dec 2018 19:49:07 +0300 Subject: [PATCH 5/7] Get rid of top level 'debug' folder --- core/kotlinx-coroutines-debug/src/{debug => }/AgentPremain.kt | 0 core/kotlinx-coroutines-debug/src/{debug => }/CoroutineState.kt | 0 core/kotlinx-coroutines-debug/src/{debug => }/DebugProbes.kt | 0 .../src/{debug => }/internal/DebugProbesImpl.kt | 0 .../src/{debug => }/internal/NoOpProbes.kt | 0 .../test/{debug => }/CoroutinesDumpTest.kt | 0 core/kotlinx-coroutines-debug/test/{debug => }/DebugProbesTest.kt | 0 .../test/{debug => }/HierarchyToStringTest.kt | 0 .../test/{debug => }/SanitizedProbesTest.kt | 0 .../test/{debug => }/ScopedBuildersTest.kt | 0 .../test/{debug => }/StartModeProbesTest.kt | 0 .../kotlinx-coroutines-debug/test/{debug => }/StracktraceUtils.kt | 0 12 files changed, 0 insertions(+), 0 deletions(-) rename core/kotlinx-coroutines-debug/src/{debug => }/AgentPremain.kt (100%) rename core/kotlinx-coroutines-debug/src/{debug => }/CoroutineState.kt (100%) rename core/kotlinx-coroutines-debug/src/{debug => }/DebugProbes.kt (100%) rename core/kotlinx-coroutines-debug/src/{debug => }/internal/DebugProbesImpl.kt (100%) rename core/kotlinx-coroutines-debug/src/{debug => }/internal/NoOpProbes.kt (100%) rename core/kotlinx-coroutines-debug/test/{debug => }/CoroutinesDumpTest.kt (100%) rename core/kotlinx-coroutines-debug/test/{debug => }/DebugProbesTest.kt (100%) rename core/kotlinx-coroutines-debug/test/{debug => }/HierarchyToStringTest.kt (100%) rename core/kotlinx-coroutines-debug/test/{debug => }/SanitizedProbesTest.kt (100%) rename core/kotlinx-coroutines-debug/test/{debug => }/ScopedBuildersTest.kt (100%) rename core/kotlinx-coroutines-debug/test/{debug => }/StartModeProbesTest.kt (100%) rename core/kotlinx-coroutines-debug/test/{debug => }/StracktraceUtils.kt (100%) diff --git a/core/kotlinx-coroutines-debug/src/debug/AgentPremain.kt b/core/kotlinx-coroutines-debug/src/AgentPremain.kt similarity index 100% rename from core/kotlinx-coroutines-debug/src/debug/AgentPremain.kt rename to core/kotlinx-coroutines-debug/src/AgentPremain.kt diff --git a/core/kotlinx-coroutines-debug/src/debug/CoroutineState.kt b/core/kotlinx-coroutines-debug/src/CoroutineState.kt similarity index 100% rename from core/kotlinx-coroutines-debug/src/debug/CoroutineState.kt rename to core/kotlinx-coroutines-debug/src/CoroutineState.kt diff --git a/core/kotlinx-coroutines-debug/src/debug/DebugProbes.kt b/core/kotlinx-coroutines-debug/src/DebugProbes.kt similarity index 100% rename from core/kotlinx-coroutines-debug/src/debug/DebugProbes.kt rename to core/kotlinx-coroutines-debug/src/DebugProbes.kt diff --git a/core/kotlinx-coroutines-debug/src/debug/internal/DebugProbesImpl.kt b/core/kotlinx-coroutines-debug/src/internal/DebugProbesImpl.kt similarity index 100% rename from core/kotlinx-coroutines-debug/src/debug/internal/DebugProbesImpl.kt rename to core/kotlinx-coroutines-debug/src/internal/DebugProbesImpl.kt diff --git a/core/kotlinx-coroutines-debug/src/debug/internal/NoOpProbes.kt b/core/kotlinx-coroutines-debug/src/internal/NoOpProbes.kt similarity index 100% rename from core/kotlinx-coroutines-debug/src/debug/internal/NoOpProbes.kt rename to core/kotlinx-coroutines-debug/src/internal/NoOpProbes.kt diff --git a/core/kotlinx-coroutines-debug/test/debug/CoroutinesDumpTest.kt b/core/kotlinx-coroutines-debug/test/CoroutinesDumpTest.kt similarity index 100% rename from core/kotlinx-coroutines-debug/test/debug/CoroutinesDumpTest.kt rename to core/kotlinx-coroutines-debug/test/CoroutinesDumpTest.kt diff --git a/core/kotlinx-coroutines-debug/test/debug/DebugProbesTest.kt b/core/kotlinx-coroutines-debug/test/DebugProbesTest.kt similarity index 100% rename from core/kotlinx-coroutines-debug/test/debug/DebugProbesTest.kt rename to core/kotlinx-coroutines-debug/test/DebugProbesTest.kt diff --git a/core/kotlinx-coroutines-debug/test/debug/HierarchyToStringTest.kt b/core/kotlinx-coroutines-debug/test/HierarchyToStringTest.kt similarity index 100% rename from core/kotlinx-coroutines-debug/test/debug/HierarchyToStringTest.kt rename to core/kotlinx-coroutines-debug/test/HierarchyToStringTest.kt diff --git a/core/kotlinx-coroutines-debug/test/debug/SanitizedProbesTest.kt b/core/kotlinx-coroutines-debug/test/SanitizedProbesTest.kt similarity index 100% rename from core/kotlinx-coroutines-debug/test/debug/SanitizedProbesTest.kt rename to core/kotlinx-coroutines-debug/test/SanitizedProbesTest.kt diff --git a/core/kotlinx-coroutines-debug/test/debug/ScopedBuildersTest.kt b/core/kotlinx-coroutines-debug/test/ScopedBuildersTest.kt similarity index 100% rename from core/kotlinx-coroutines-debug/test/debug/ScopedBuildersTest.kt rename to core/kotlinx-coroutines-debug/test/ScopedBuildersTest.kt diff --git a/core/kotlinx-coroutines-debug/test/debug/StartModeProbesTest.kt b/core/kotlinx-coroutines-debug/test/StartModeProbesTest.kt similarity index 100% rename from core/kotlinx-coroutines-debug/test/debug/StartModeProbesTest.kt rename to core/kotlinx-coroutines-debug/test/StartModeProbesTest.kt diff --git a/core/kotlinx-coroutines-debug/test/debug/StracktraceUtils.kt b/core/kotlinx-coroutines-debug/test/StracktraceUtils.kt similarity index 100% rename from core/kotlinx-coroutines-debug/test/debug/StracktraceUtils.kt rename to core/kotlinx-coroutines-debug/test/StracktraceUtils.kt From 7a6fd89c04b3ee972136c0648700f8500dfb0f23 Mon Sep 17 00:00:00 2001 From: Vsevolod Tolstopyatov Date: Wed, 12 Dec 2018 19:08:32 +0300 Subject: [PATCH 6/7] Debug agent cleanup * Readme * Do not fail on Windows during signal handler installation * Do not warn about missing artificial stackframe --- .../src/channels/AbstractChannel.kt | 2 +- core/kotlinx-coroutines-debug/README.md | 14 +++++++------- core/kotlinx-coroutines-debug/src/AgentPremain.kt | 8 ++++++-- .../src/internal/DebugProbesImpl.kt | 11 +---------- .../test/DebugProbesTest.kt | 1 + 5 files changed, 16 insertions(+), 20 deletions(-) diff --git a/common/kotlinx-coroutines-core-common/src/channels/AbstractChannel.kt b/common/kotlinx-coroutines-core-common/src/channels/AbstractChannel.kt index 48692f1d88..f0f22ad130 100644 --- a/common/kotlinx-coroutines-core-common/src/channels/AbstractChannel.kt +++ b/common/kotlinx-coroutines-core-common/src/channels/AbstractChannel.kt @@ -859,7 +859,7 @@ internal abstract class AbstractChannel : AbstractSendChannel(), Channel) { - if (result.closeCause != null) recoverStackTrace(throw result.receiveException) + if (result.closeCause != null) throw recoverStackTrace(result.receiveException) return false } return true diff --git a/core/kotlinx-coroutines-debug/README.md b/core/kotlinx-coroutines-debug/README.md index f055ffc627..e12c742647 100644 --- a/core/kotlinx-coroutines-debug/README.md +++ b/core/kotlinx-coroutines-debug/README.md @@ -4,19 +4,19 @@ Debugging facilities for `kotlinx.coroutines` on JVM. ### Overview -This module provides a debug JVM agent which allows to track and trace alive coroutines. -Main entry point to debug facilities is [DebugProbes]. +This module provides a debug JVM agent which allows to track and trace existing coroutines. +The main entry point to debug facilities is [DebugProbes] API. Call to [DebugProbes.install] installs debug agent via ByteBuddy and starts to spy on coroutines when they are created, suspended or resumed. -After that you can use [DebugProbes.dumpCoroutines] to print all active (suspended or running) coroutines, including their state, creation and +After that, you can use [DebugProbes.dumpCoroutines] to print all active (suspended or running) coroutines, including their state, creation and suspension stacktraces. -Additionally, it is possible to process list of such coroutines via [DebugProbes.dumpCoroutinesState] or dump isolated parts -of coroutines hierarchies referenced by [Job] instance using [DebugProbes.printHierarchy]. +Additionally, it is possible to process the list of such coroutines via [DebugProbes.dumpCoroutinesState] or dump isolated parts +of coroutines hierarchy referenced by a [Job] instance using [DebugProbes.printHierarchy]. ### Using as JVM agent -Additionally, it is possible to use this module as standalone JVM agent to enable debug probes on the application startup. -You can run your application with additional argument: `-javaagent:kotlinx-coroutines-debug-1.1.0.jar`. +It is possible to use this module as a standalone JVM agent to enable debug probes on the application startup. +You can run your application with an additional argument: `-javaagent:kotlinx-coroutines-debug-1.1.0.jar`. Additionally, on Linux and Mac OS X you can use `kill -5 $pid` command in order to force your application to print all alive coroutines. diff --git a/core/kotlinx-coroutines-debug/src/AgentPremain.kt b/core/kotlinx-coroutines-debug/src/AgentPremain.kt index 5745439e9c..1ff996e5aa 100644 --- a/core/kotlinx-coroutines-debug/src/AgentPremain.kt +++ b/core/kotlinx-coroutines-debug/src/AgentPremain.kt @@ -19,8 +19,12 @@ internal object AgentPremain { } private fun installSignalHandler() { - Signal.handle(Signal("TRAP") ) { // kill -5 - DebugProbes.dumpCoroutines() + try { + Signal.handle(Signal("TRAP")) { // kill -5 + DebugProbes.dumpCoroutines() + } + } catch (t: Throwable) { + System.err.println("Failed to install signal handler: $t") } } } diff --git a/core/kotlinx-coroutines-debug/src/internal/DebugProbesImpl.kt b/core/kotlinx-coroutines-debug/src/internal/DebugProbesImpl.kt index c40e14ca64..b78f4eba9b 100644 --- a/core/kotlinx-coroutines-debug/src/internal/DebugProbesImpl.kt +++ b/core/kotlinx-coroutines-debug/src/internal/DebugProbesImpl.kt @@ -151,11 +151,7 @@ internal object DebugProbesImpl { @Synchronized private fun updateState(owner: ArtificialStackFrame<*>?, frame: Continuation<*>, state: State) { - val coroutineState = capturedCoroutines[owner] - if (coroutineState == null) { - warn(frame, state) - return - } + val coroutineState = capturedCoroutines[owner] ?: return coroutineState.updateState(state, frame) } @@ -257,9 +253,4 @@ internal object DebugProbesImpl { } private val StackTraceElement.isInternalMethod: Boolean get() = className.startsWith("kotlinx.coroutines") - - private fun warn(frame: Continuation<*>, state: State) { - // TODO make this warning configurable or not a warning at all - System.err.println("Failed to find an owner of the frame $frame while transferring it to the state $state") - } } diff --git a/core/kotlinx-coroutines-debug/test/DebugProbesTest.kt b/core/kotlinx-coroutines-debug/test/DebugProbesTest.kt index 04c1b05f00..9dd4d7cec0 100644 --- a/core/kotlinx-coroutines-debug/test/DebugProbesTest.kt +++ b/core/kotlinx-coroutines-debug/test/DebugProbesTest.kt @@ -66,6 +66,7 @@ class DebugProbesTest : TestBase() { @Test fun testAsyncWithSanitizedProbes() = DebugProbes.withDebugProbes { + DebugProbes.sanitizeStackTraces = true runTest { val deferred = createDeferred() val traces = listOf( From 3781a821a11a64670b5a3ffa3c276f1533332ad7 Mon Sep 17 00:00:00 2001 From: Vsevolod Tolstopyatov Date: Thu, 13 Dec 2018 11:58:29 +0300 Subject: [PATCH 7/7] Repackage byte-buddy along with debug agent (so it shouldn't be a dependency of target process), use shadow plugin for that to avoid clashes with other byte-buddy versions and publish shadow jar instead of regular one for debug module --- build.gradle | 2 +- core/kotlinx-coroutines-debug/build.gradle | 12 ++++++ .../src/CoroutineState.kt | 11 ++++- gradle/publish-bintray.gradle | 42 ++++++++++--------- 4 files changed, 45 insertions(+), 22 deletions(-) diff --git a/build.gradle b/build.gradle index 52ad4ab282..4125af49c2 100644 --- a/build.gradle +++ b/build.gradle @@ -40,7 +40,7 @@ buildscript { classpath "com.moowork.gradle:gradle-node-plugin:$gradle_node_version" // JMH plugins - classpath "com.github.jengelman.gradle.plugins:shadow:2.0.2" + classpath "com.github.jengelman.gradle.plugins:shadow:4.0.2" classpath "me.champeau.gradle:jmh-gradle-plugin:0.4.7" classpath "net.ltgt.gradle:gradle-apt-plugin:0.10" } diff --git a/core/kotlinx-coroutines-debug/build.gradle b/core/kotlinx-coroutines-debug/build.gradle index b7a7d3d089..d54b2b67df 100644 --- a/core/kotlinx-coroutines-debug/build.gradle +++ b/core/kotlinx-coroutines-debug/build.gradle @@ -2,6 +2,8 @@ * Copyright 2016-2018 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license. */ +apply plugin: "com.github.johnrengelman.shadow" + dependencies { compile "net.bytebuddy:byte-buddy:$byte_buddy_version" compile "net.bytebuddy:byte-buddy-agent:$byte_buddy_version" @@ -13,3 +15,13 @@ jar { attributes "Can-Redefine-Classes": "true" } } + +shadowJar { + classifier null + // Shadow only byte buddy, do not package kotlin stdlib + dependencies { + include(dependency("net.bytebuddy:byte-buddy:$byte_buddy_version")) + include(dependency("net.bytebuddy:byte-buddy-agent:$byte_buddy_version")) + } + relocate 'net.bytebuddy', 'kotlinx.coroutines.repackaged.net.bytebuddy' +} diff --git a/core/kotlinx-coroutines-debug/src/CoroutineState.kt b/core/kotlinx-coroutines-debug/src/CoroutineState.kt index 78f290b8b8..31aa10de01 100644 --- a/core/kotlinx-coroutines-debug/src/CoroutineState.kt +++ b/core/kotlinx-coroutines-debug/src/CoroutineState.kt @@ -97,7 +97,16 @@ public data class CoroutineState internal constructor( * Current state of the coroutine. */ public enum class State { - CREATED, // Not yet started + /** + * Created, but not yet started + */ + CREATED, + /** + * Started and running + */ RUNNING, + /** + * Suspended + */ SUSPENDED } diff --git a/gradle/publish-bintray.gradle b/gradle/publish-bintray.gradle index f0018eeeb9..23c38bd267 100644 --- a/gradle/publish-bintray.gradle +++ b/gradle/publish-bintray.gradle @@ -8,6 +8,7 @@ apply plugin: 'maven' apply plugin: 'maven-publish' apply plugin: 'com.jfrog.bintray' apply plugin: 'com.jfrog.artifactory' +apply plugin: "com.github.johnrengelman.shadow" apply from: project.rootProject.file('gradle/maven-central.gradle') @@ -16,13 +17,13 @@ def coroutines_core = platformLib("kotlinx-coroutines-core", platform) // ------------- tasks -def isNative = project.name.endsWith("native") +def isNative() { return project.name.endsWith("native") } def bUser = project.hasProperty('bintrayUser') ? project.property('bintrayUser') : System.getenv('BINTRAY_USER') def bKey = project.hasProperty('bintrayApiKey') ? project.property('bintrayApiKey') : System.getenv('BINTRAY_API_KEY') task sourcesJar(type: Jar) { classifier = 'sources' - if (!isNative) { + if (!isNative()) { from sourceSets.main.allSource } @@ -32,19 +33,15 @@ task sourcesJar(type: Jar) { } } + publishing { repositories { maven { url = 'https://kotlin.bintray.com/kotlinx' } } publications { - maven(MavenPublication) { - if (!isNative) { - from components.java - artifact javadocJar - artifact sourcesJar - } - pom.withXml(configureMavenCentralMetadata) + maven(MavenPublication) { publication -> + preparePublication(publication) } } } @@ -58,15 +55,8 @@ artifactory { password = bKey } - publications { - maven(MavenPublication) { - if (!isNative) { - from components.java - artifact javadocJar - artifact sourcesJar - } - pom.withXml(configureMavenCentralMetadata) - } + maven(MavenPublication) { publication -> + preparePublication(publication) } defaults { @@ -75,9 +65,21 @@ artifactory { } } +def preparePublication(MavenPublication publication) { + if (!isNative()) { + if (project.name == "kotlinx-coroutines-debug") { + project.shadow.component(publication) + } else { + publication.from components.java + } + publication.artifact javadocJar + publication.artifact sourcesJar + } + publication.pom.withXml(configureMavenCentralMetadata) +} + task publishDevelopSnapshot() { def branch = System.getenv('currentBranch') - println "Current branch: $branch" if (branch == "develop") { dependsOn(":artifactoryPublish") } @@ -112,7 +114,7 @@ bintrayUpload.doFirst { } // TODO :kludge this is required to disable publish of metadata for all but native -if (!isNative) { +if (!isNative()) { afterEvaluate { publishing.publications.each { pub -> pub.gradleModuleMetadataFile = null