Skip to content

Commit

Permalink
Introduce flag to disable creation stacktrace capturing in DebugProbes
Browse files Browse the repository at this point in the history
  • Loading branch information
qwwdfsad committed Mar 13, 2020
1 parent a7cbad8 commit 99b9ab0
Show file tree
Hide file tree
Showing 15 changed files with 210 additions and 32 deletions.
1 change: 1 addition & 0 deletions README.md
Expand Up @@ -277,6 +277,7 @@ The `develop` branch is pushed to `master` during release.
[ListenableFuture.await]: https://kotlin.github.io/kotlinx.coroutines/kotlinx-coroutines-guava/kotlinx.coroutines.guava/com.google.common.util.concurrent.-listenable-future/await.html
<!--- MODULE kotlinx-coroutines-play-services -->
<!--- INDEX kotlinx.coroutines.tasks -->
[Task.await]: https://kotlin.github.io/kotlinx.coroutines/kotlinx-coroutines-play-services/kotlinx.coroutines.tasks/com.google.android.gms.tasks.-task/await.html
<!--- MODULE kotlinx-coroutines-reactive -->
<!--- INDEX kotlinx.coroutines.reactive -->
[Publisher.collect]: https://kotlin.github.io/kotlinx.coroutines/kotlinx-coroutines-reactive/kotlinx.coroutines.reactive/org.reactivestreams.-publisher/collect.html
Expand Down
23 changes: 20 additions & 3 deletions kotlinx-coroutines-debug/README.md
Expand Up @@ -55,9 +55,20 @@ stacktraces will be dumped to the console.

### Using as JVM agent

It is possible to use this module as a standalone JVM agent to enable debug probes on the application startup.
Debug module can also be used 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.3.4.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.
When used as Java agent, `"kotlinx.coroutines.debug.enable.creation.stack.trace"` system property can be used to control
[DebugProbes.enableCreationStackTraces] along with agent startup.

### Using in production environment

It is possible to run an application in production environments with debug probes in order to monitor its
state and improve its observability.
For that, it is strongly recommended to switch off [DebugProbes.enableCreationStackTraces] property to significantly
reduce the overhead of debug probes and make it insignificant.
With creation stack-traces disabled, the typical overhead of enabled debug probes is a single-digit percentage of the total
application throughput.


### Example of usage
Expand Down Expand Up @@ -128,8 +139,13 @@ Dumping only deferred

### 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].
API is experimental, and it is not guaranteed it won't be changed (while it is marked as `@ExperimentalCoroutinesApi`).
Like the rest of experimental API, `DebugProbes` is carefully designed, tested and ready to use in both test and production
environments. It is marked as experimental to leave us the room to enrich the output data in a potentially backwards incompatible manner
to further improve diagnostics and debugging experience.

The output format of [DebugProbes] can be changed in the future and it is not recommended to rely on the string representation
of the dump programmatically.

### Debug agent and Android

Expand Down Expand Up @@ -161,6 +177,7 @@ java.lang.NoClassDefFoundError: Failed resolution of: Ljava/lang/management/Mana
[DebugProbes.dumpCoroutinesInfo]: https://kotlin.github.io/kotlinx.coroutines/kotlinx-coroutines-debug/kotlinx.coroutines.debug/-debug-probes/dump-coroutines-info.html
[DebugProbes.printJob]: https://kotlin.github.io/kotlinx.coroutines/kotlinx-coroutines-debug/kotlinx.coroutines.debug/-debug-probes/print-job.html
[DebugProbes.printScope]: https://kotlin.github.io/kotlinx.coroutines/kotlinx-coroutines-debug/kotlinx.coroutines.debug/-debug-probes/print-scope.html
[DebugProbes.enableCreationStackTraces]: https://kotlin.github.io/kotlinx.coroutines/kotlinx-coroutines-debug/kotlinx.coroutines.debug/-debug-probes/enable-creation-stack-traces.html
<!--- INDEX kotlinx.coroutines.debug.junit4 -->
[CoroutinesTimeout]: https://kotlin.github.io/kotlinx.coroutines/kotlinx-coroutines-debug/kotlinx.coroutines.debug.junit4/-coroutines-timeout/index.html
<!--- END -->
16 changes: 14 additions & 2 deletions kotlinx-coroutines-debug/api/kotlinx-coroutines-debug.api
Expand Up @@ -13,6 +13,7 @@ public final class kotlinx/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 dumpCoroutinesInfo ()Ljava/util/List;
public final fun getEnableCreationStackTraces ()Z
public final fun getSanitizeStackTraces ()Z
public final fun install ()V
public final fun isInstalled ()Z
Expand All @@ -22,6 +23,7 @@ public final class kotlinx/coroutines/debug/DebugProbes {
public final fun printScope (Lkotlinx/coroutines/CoroutineScope;Ljava/io/PrintStream;)V
public static synthetic fun printScope$default (Lkotlinx/coroutines/debug/DebugProbes;Lkotlinx/coroutines/CoroutineScope;Ljava/io/PrintStream;ILjava/lang/Object;)V
public final fun scopeToString (Lkotlinx/coroutines/CoroutineScope;)Ljava/lang/String;
public final fun setEnableCreationStackTraces (Z)V
public final fun setSanitizeStackTraces (Z)V
public final fun uninstall ()V
public final fun withDebugProbes (Lkotlin/jvm/functions/Function0;)V
Expand All @@ -35,17 +37,27 @@ public final class kotlinx/coroutines/debug/State : java/lang/Enum {
public static fun values ()[Lkotlinx/coroutines/debug/State;
}

public synthetic class kotlinx/coroutines/debug/internal/DebugProbesImplSequenceNumberRefVolatile {
public fun <init> (J)V
}

public final class kotlinx/coroutines/debug/junit4/CoroutinesTimeout : org/junit/rules/TestRule {
public static final field Companion Lkotlinx/coroutines/debug/junit4/CoroutinesTimeout$Companion;
public fun <init> (JZ)V
public synthetic fun <init> (JZILkotlin/jvm/internal/DefaultConstructorMarker;)V
public fun <init> (JZZ)V
public synthetic fun <init> (JZZILkotlin/jvm/internal/DefaultConstructorMarker;)V
public fun apply (Lorg/junit/runners/model/Statement;Lorg/junit/runner/Description;)Lorg/junit/runners/model/Statement;
}

public final class kotlinx/coroutines/debug/junit4/CoroutinesTimeout$Companion {
public final fun seconds (I)Lkotlinx/coroutines/debug/junit4/CoroutinesTimeout;
public final fun seconds (IZ)Lkotlinx/coroutines/debug/junit4/CoroutinesTimeout;
public final fun seconds (IZZ)Lkotlinx/coroutines/debug/junit4/CoroutinesTimeout;
public final fun seconds (J)Lkotlinx/coroutines/debug/junit4/CoroutinesTimeout;
public final fun seconds (JZ)Lkotlinx/coroutines/debug/junit4/CoroutinesTimeout;
public static synthetic fun seconds$default (Lkotlinx/coroutines/debug/junit4/CoroutinesTimeout$Companion;IZILjava/lang/Object;)Lkotlinx/coroutines/debug/junit4/CoroutinesTimeout;
public static synthetic fun seconds$default (Lkotlinx/coroutines/debug/junit4/CoroutinesTimeout$Companion;JZILjava/lang/Object;)Lkotlinx/coroutines/debug/junit4/CoroutinesTimeout;
public final fun seconds (JZZ)Lkotlinx/coroutines/debug/junit4/CoroutinesTimeout;
public static synthetic fun seconds$default (Lkotlinx/coroutines/debug/junit4/CoroutinesTimeout$Companion;IZZILjava/lang/Object;)Lkotlinx/coroutines/debug/junit4/CoroutinesTimeout;
public static synthetic fun seconds$default (Lkotlinx/coroutines/debug/junit4/CoroutinesTimeout$Companion;JZZILjava/lang/Object;)Lkotlinx/coroutines/debug/junit4/CoroutinesTimeout;
}

5 changes: 5 additions & 0 deletions kotlinx-coroutines-debug/src/AgentPremain.kt
Expand Up @@ -11,6 +11,10 @@ import java.lang.instrument.*
@Suppress("unused")
internal object AgentPremain {

private val enableCreationStackTraces =
System.getProperty("kotlinx.coroutines.debug.enable.creation.stack.trace")?.toBoolean()
?: DebugProbes.enableCreationStackTraces

@JvmStatic
public fun premain(args: String?, instrumentation: Instrumentation) {
Installer.premain(args, instrumentation)
Expand All @@ -24,6 +28,7 @@ internal object AgentPremain {
if (DebugProbes.isInstalled) {
// Case with 'isInstalled' changed between this check-and-act is not considered
// a real debug probes use-case, thus is not guarded against.
DebugProbes.enableCreationStackTraces = enableCreationStackTraces
DebugProbes.dumpCoroutines()
} else {
println("""Cannot perform coroutines dump, debug probes are disabled""")
Expand Down
6 changes: 4 additions & 2 deletions kotlinx-coroutines-debug/src/CoroutineInfo.kt
Expand Up @@ -16,7 +16,7 @@ import kotlin.coroutines.jvm.internal.*
@ExperimentalCoroutinesApi
public class CoroutineInfo internal constructor(
val context: CoroutineContext,
private val creationStackBottom: CoroutineStackFrame,
private val creationStackBottom: CoroutineStackFrame?,
@JvmField internal val sequenceNumber: Long
) {

Expand All @@ -28,6 +28,7 @@ public class CoroutineInfo internal constructor(

/**
* Creation stacktrace of the coroutine.
* Can be empty if [DebugProbes.enableCreationStackTraces] is not set.
*/
public val creationStackTrace: List<StackTraceElement> get() = creationStackTrace()

Expand Down Expand Up @@ -66,8 +67,9 @@ public class CoroutineInfo internal constructor(
}

private fun creationStackTrace(): List<StackTraceElement> {
val bottom = creationStackBottom ?: return emptyList()
// Skip "Coroutine creation stacktrace" frame
return sequence<StackTraceElement> { yieldFrames(creationStackBottom.callerFrame) }.toList()
return sequence<StackTraceElement> { yieldFrames(bottom.callerFrame) }.toList()
}

private tailrec suspend fun SequenceScope<StackTraceElement>.yieldFrames(frame: CoroutineStackFrame?) {
Expand Down
18 changes: 14 additions & 4 deletions kotlinx-coroutines-debug/src/DebugProbes.kt
Expand Up @@ -28,20 +28,30 @@ import kotlin.coroutines.*
* * `probeCoroutineCreated` is invoked on every coroutine creation using stdlib intrinsics.
*
* Overhead:
* * 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.
* * Every created coroutine is stored in a concurrent hash map and hash map is looked up and
* updated on each suspension and resumption.
* * If [DebugProbes.enableCreationStackTraces] is enabled, stack trace of the current thread is captured on
* each created coroutine that is a rough equivalent of throwing an exception per each created coroutine.
*/
@ExperimentalCoroutinesApi
public object DebugProbes {

/**
* Whether coroutine creation stacktraces should be sanitized.
* Whether coroutine creation stack traces should be sanitized.
* Sanitization removes all frames from `kotlinx.coroutines` package except
* the first one and the last one to simplify diagnostic.
*/
public var sanitizeStackTraces: Boolean = true

/**
* Whether coroutine creation stack traces should be captured.
* When enabled, for each created coroutine a stack trace of the current
* thread is captured and attached to the coroutine.
* This option can be useful during local debug sessions, but is recommended
* to be disabled in production environments to avoid stack trace dumping overhead.
*/
public var enableCreationStackTraces: Boolean = true

/**
* Determines whether debug probes were [installed][DebugProbes.install].
*/
Expand Down
29 changes: 20 additions & 9 deletions kotlinx-coroutines-debug/src/internal/DebugProbesImpl.kt
Expand Up @@ -334,18 +334,23 @@ internal object DebugProbesImpl {
* even more verbose (it will attach coroutine creation stacktrace to all exceptions),
* and then using CoroutineOwner completion as unique identifier of coroutineSuspended/resumed calls.
*/
val stacktrace = sanitizeStackTrace(Exception())
val frame = stacktrace.foldRight<StackTraceElement, CoroutineStackFrame?>(null) { frame, acc ->
object : CoroutineStackFrame {
override val callerFrame: CoroutineStackFrame? = acc
override fun getStackTraceElement(): StackTraceElement = frame

val frame = if (DebugProbes.enableCreationStackTraces) {
val stacktrace = sanitizeStackTrace(Exception())
stacktrace.foldRight<StackTraceElement, CoroutineStackFrame?>(null) { frame, acc ->
object : CoroutineStackFrame {
override val callerFrame: CoroutineStackFrame? = acc
override fun getStackTraceElement(): StackTraceElement = frame
}
}
}!!
} else {
null
}

return createOwner(completion, frame)
}

private fun <T> createOwner(completion: Continuation<T>, frame: CoroutineStackFrame): Continuation<T> {
private fun <T> createOwner(completion: Continuation<T>, frame: CoroutineStackFrame?): Continuation<T> {
if (!isInstalled) return completion
val info = CoroutineInfo(completion.context, frame, sequenceNumber.incrementAndGet())
val owner = CoroutineOwner(completion, info, frame)
Expand All @@ -372,8 +377,14 @@ internal object DebugProbesImpl {
private class CoroutineOwner<T>(
@JvmField val delegate: Continuation<T>,
@JvmField val info: CoroutineInfo,
frame: CoroutineStackFrame
) : Continuation<T> by delegate, CoroutineStackFrame by frame {
private val frame: CoroutineStackFrame?
) : Continuation<T> by delegate, CoroutineStackFrame {

override val callerFrame: CoroutineStackFrame?
get() = frame?.callerFrame

override fun getStackTraceElement(): StackTraceElement? = frame?.getStackTraceElement()

override fun resumeWith(result: Result<T>) {
probeCoroutineCompleted(this)
delegate.resumeWith(result)
Expand Down
32 changes: 27 additions & 5 deletions kotlinx-coroutines-debug/src/junit4/CoroutinesTimeout.kt
Expand Up @@ -17,6 +17,8 @@ import java.util.concurrent.*
*
* Additionally, this rule installs [DebugProbes] and dumps all coroutines at the moment of the timeout.
* It may cancel coroutines on timeout if [cancelOnTimeout] set to `true`.
* [enableCoroutineCreationStackTraces] controls the corresponding [DebugProbes.enableCreationStackTraces] property
* and can be optionally disabled to speed-up tests if creation stack traces are not needed.
*
* Example of usage:
* ```
Expand All @@ -35,30 +37,50 @@ import java.util.concurrent.*
*/
public class CoroutinesTimeout(
private val testTimeoutMs: Long,
private val cancelOnTimeout: Boolean = false
private val cancelOnTimeout: Boolean = false,
private val enableCoroutineCreationStackTraces: Boolean = true
) : TestRule {

@Suppress("UNUSED") // Binary compatibility
constructor(testTimeoutMs: Long, cancelOnTimeout: Boolean = false) : this(testTimeoutMs, cancelOnTimeout, true)

init {
require(testTimeoutMs > 0) { "Expected positive test timeout, but had $testTimeoutMs" }
/*
* Install probes in the constructor, so all the coroutines launched from within
* target test constructor will be captured
*/
// Do not preserve previous state for unit-test environment
DebugProbes.enableCreationStackTraces = enableCoroutineCreationStackTraces
DebugProbes.install()
}

companion object {
/**
* Creates [CoroutinesTimeout] rule with the given timeout in seconds.
*/
public fun seconds(seconds: Int, cancelOnTimeout: Boolean = false): CoroutinesTimeout =
seconds(seconds.toLong(), cancelOnTimeout)
@JvmOverloads
public fun seconds(
seconds: Int,
cancelOnTimeout: Boolean = false,
enableCoroutineCreationStackTraces: Boolean = true
): CoroutinesTimeout =
seconds(seconds.toLong(), cancelOnTimeout, enableCoroutineCreationStackTraces)

/**
* Creates [CoroutinesTimeout] rule with the given timeout in seconds.
*/
public fun seconds(seconds: Long, cancelOnTimeout: Boolean = false): CoroutinesTimeout =
CoroutinesTimeout(TimeUnit.SECONDS.toMillis(seconds), cancelOnTimeout) // Overflow is properly handled by TimeUnit
@JvmOverloads
public fun seconds(
seconds: Long,
cancelOnTimeout: Boolean = false,
enableCoroutineCreationStackTraces: Boolean = true
): CoroutinesTimeout =
CoroutinesTimeout(
TimeUnit.SECONDS.toMillis(seconds), // Overflow is properly handled by TimeUnit
cancelOnTimeout,
enableCoroutineCreationStackTraces
)
}

/**
Expand Down
3 changes: 2 additions & 1 deletion kotlinx-coroutines-debug/test/DebugTestBase.kt
Expand Up @@ -18,6 +18,7 @@ open class DebugTestBase : TestBase() {
open fun setUp() {
before()
DebugProbes.sanitizeStackTraces = false
DebugProbes.enableCreationStackTraces = true
DebugProbes.install()
}

Expand All @@ -29,4 +30,4 @@ open class DebugTestBase : TestBase() {
onCompletion()
}
}
}
}
44 changes: 44 additions & 0 deletions kotlinx-coroutines-debug/test/DumpWithoutCreationStackTraceTest.kt
@@ -0,0 +1,44 @@
/*
* Copyright 2016-2020 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 DumpWithoutCreationStackTraceTest : DebugTestBase() {
@Before
override fun setUp() {
super.setUp()
DebugProbes.enableCreationStackTraces = false
}

@Test
fun testCoroutinesDump() = runTest {
val deferred = createActiveDeferred()
yield()
verifyDump(
"Coroutine \"coroutine#1\":BlockingCoroutine{Active}@70d1cb56, state: RUNNING\n" +
"\tat java.lang.Thread.getStackTrace(Thread.java:1559)\n" +
"\tat kotlinx.coroutines.debug.internal.DebugProbesImpl.enhanceStackTraceWithThreadDump(DebugProbesImpl.kt:188)\n" +
"\tat kotlinx.coroutines.debug.internal.DebugProbesImpl.dumpCoroutinesSynchronized(DebugProbesImpl.kt:153)\n" +
"\tat kotlinx.coroutines.debug.internal.DebugProbesImpl.dumpCoroutines(DebugProbesImpl.kt:141)",

"Coroutine \"coroutine#2\":DeferredCoroutine{Active}@383fa309, state: SUSPENDED\n" +
"\tat kotlinx.coroutines.debug.DumpWithoutCreationStackTraceTest\$createActiveDeferred\$1.invokeSuspend(DumpWithoutCreationStackTraceTest.kt:63)"
)
deferred.cancelAndJoin()
}


private fun CoroutineScope.createActiveDeferred(): Deferred<*> = async {
suspendingMethod()
assertTrue(true)
}

private suspend fun suspendingMethod() {
delay(Long.MAX_VALUE)
}
}
4 changes: 2 additions & 2 deletions kotlinx-coroutines-debug/test/StracktraceUtils.kt
Expand Up @@ -80,14 +80,14 @@ public fun verifyDump(vararg traces: String, ignoredCoroutine: String? = null) {

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)
assertEquals(expected.size, actual.size, "Creation stacktrace should be part of the expected input")

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) {
for (i in expectedLines.indices) {
assertEquals(expectedLines[i], actualLines[i])
}
}
Expand Down

0 comments on commit 99b9ab0

Please sign in to comment.