Obtain real stacktrace of running coroutines in debug agent
* Capture thread of coroutine when it's transited to running state
* During dump retrieve the stacktrace of captured thread for running coroutines and merge it with metadata-based stacktrace
Fixes #997
diff --git a/kotlinx-coroutines-debug/src/CoroutineState.kt b/kotlinx-coroutines-debug/src/CoroutineState.kt
index 3441de8..9d4489d 100644
--- a/kotlinx-coroutines-debug/src/CoroutineState.kt
+++ b/kotlinx-coroutines-debug/src/CoroutineState.kt
@@ -39,6 +39,9 @@
private var _state: State = State.CREATED
+ @JvmField
+ internal var lastObservedThread: Thread? = null
+
private var lastObservedFrame: CoroutineStackFrame? = null
// Copy constructor
@@ -66,9 +69,15 @@
}
internal fun updateState(state: State, frame: Continuation<*>) {
- if (_state == state && lastObservedFrame != null) return
+ // Propagate only duplicating transitions to running for KT-29997
+ if (_state == state && state == State.SUSPENDED && lastObservedFrame != null) return
_state = state
lastObservedFrame = frame as? CoroutineStackFrame
+ if (state == State.RUNNING) {
+ lastObservedThread = Thread.currentThread()
+ } else {
+ lastObservedThread = null
+ }
}
/**
@@ -83,7 +92,6 @@
frame.getStackTraceElement()?.let { result.add(sanitize(it)) }
frame = frame.callerFrame
}
-
return result
}
}
diff --git a/kotlinx-coroutines-debug/src/internal/DebugProbesImpl.kt b/kotlinx-coroutines-debug/src/internal/DebugProbesImpl.kt
index 5c1aec1..5c2c594 100644
--- a/kotlinx-coroutines-debug/src/internal/DebugProbesImpl.kt
+++ b/kotlinx-coroutines-debug/src/internal/DebugProbesImpl.kt
@@ -117,22 +117,89 @@
.asSequence()
.sortedBy { it.value.sequenceNumber }
.forEach { (key, value) ->
- val state = if (value.state == State.RUNNING)
+ val observedStackTrace = value.lastObservedStackTrace()
+ val enhancedStackTrace = enhanceStackTraceWithThreadDump(value, observedStackTrace)
+ val state = if (value.state == State.RUNNING && enhancedStackTrace === observedStackTrace)
"${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())
+ printStackTrace(enhancedStackTrace)
}
}
}
+ /**
+ * Tries to enhance [coroutineTrace] (obtained by call to [CoroutineState.lastObservedStackTrace]) with
+ * thread dump of [CoroutineState.lastObservedThread].
+ *
+ * Returns [coroutineTrace] if enhancement was unsuccessful or the enhancement result.
+ */
+ private fun enhanceStackTraceWithThreadDump(
+ state: CoroutineState,
+ coroutineTrace: List<StackTraceElement>
+ ): List<StackTraceElement> {
+ val thread = state.lastObservedThread
+ if (state.state != State.RUNNING || thread == null) return coroutineTrace
+ // Avoid security manager issues
+ val actualTrace = runCatching { thread.stackTrace }.getOrNull()
+ ?: return coroutineTrace
+
+ /*
+ * Here goes heuristic that tries to merge two stacktraces: real one
+ * (that has at least one but usually not so many suspend function frames)
+ * and coroutine one that has only suspend function frames.
+ *
+ * Heuristic:
+ * 1) Dump lastObservedThread
+ * 2) Find the next frame after BaseContinuationImpl.resumeWith (continuation machinery).
+ * Invariant: this method is called under the lock, so such method **should** be present
+ * in continuation stacktrace.
+ *
+ * 3) Find target method in continuation stacktrace (metadata-based)
+ * 4) Prepend dumped stacktrace (trimmed by target frame) to continuation stacktrace
+ *
+ * Heuristic may fail on recursion and overloads, but it will be automatically improved
+ * with KT-29997
+ */
+ val indexOfResumeWith = actualTrace.indexOfFirst {
+ it.className == "kotlin.coroutines.jvm.internal.BaseContinuationImpl" &&
+ it.methodName == "resumeWith" &&
+ it.fileName == "ContinuationImpl.kt"
+ }
+
+ // We haven't found "BaseContinuationImpl.resumeWith" resume call in stacktrace
+ // This is some inconsistency in machinery, do not fail, fallback
+ val continuationFrame = actualTrace.getOrNull(indexOfResumeWith - 1)
+ ?: return coroutineTrace
+
+ val continuationStartFrame = coroutineTrace.indexOfFirst {
+ it.fileName == continuationFrame.fileName &&
+ it.className == continuationFrame.className &&
+ it.methodName == continuationFrame.methodName
+ } + 1
+
+ if (continuationStartFrame == 0) return coroutineTrace
+
+ val expectedSize = indexOfResumeWith + coroutineTrace.size - continuationStartFrame
+ val result = ArrayList<StackTraceElement>(expectedSize)
+
+ for (index in 0 until indexOfResumeWith) {
+ result += actualTrace[index]
+ }
+
+ for (index in continuationStartFrame until coroutineTrace.size) {
+ result += coroutineTrace[index]
+ }
+
+ return result
+ }
+
private fun StringBuilder.printStackTrace(frames: List<StackTraceElement>) {
frames.forEach { frame ->
append("\n\tat $frame")
diff --git a/kotlinx-coroutines-debug/test/RunningThreadStackMergeTest.kt b/kotlinx-coroutines-debug/test/RunningThreadStackMergeTest.kt
new file mode 100644
index 0000000..b5e53bf
--- /dev/null
+++ b/kotlinx-coroutines-debug/test/RunningThreadStackMergeTest.kt
@@ -0,0 +1,150 @@
+/*
+ * Copyright 2016-2019 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.util.concurrent.*
+import kotlin.test.*
+
+class RunningThreadStackMergeTest : TestBase() {
+
+ private val testMainBlocker = CountDownLatch(1) // Test body blocks on it
+ private val coroutineBlocker = CyclicBarrier(2) // Launched coroutine blocks on it
+
+ @Before
+ fun setUp() {
+ before()
+ DebugProbes.install()
+ }
+
+ @After
+ fun tearDown() {
+ try {
+ DebugProbes.uninstall()
+ } finally {
+ onCompletion()
+ }
+ }
+
+ @Test
+ fun testStackMergeWithContext() = runTest {
+ launchCoroutine()
+ awaitCoroutineStarted()
+
+ verifyDump(
+ "Coroutine \"coroutine#1\":BlockingCoroutine{Active}@62230679", // <- this one is ignored
+ "Coroutine \"coroutine#2\":StandaloneCoroutine{Active}@50284dc4, state: RUNNING\n" +
+ "\tat sun.misc.Unsafe.park(Native Method)\n" +
+ "\tat java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)\n" +
+ "\tat java.util.concurrent.locks.AbstractQueuedSynchronizer\$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)\n" +
+ "\tat java.util.concurrent.CyclicBarrier.dowait(CyclicBarrier.java:234)\n" +
+ "\tat java.util.concurrent.CyclicBarrier.await(CyclicBarrier.java:362)\n" +
+ "\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest.nonSuspendingFun(RunningThreadStackMergeTest.kt:86)\n" +
+ "\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest.access\$nonSuspendingFun(RunningThreadStackMergeTest.kt:12)\n" +
+ "\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest\$suspendingFunction\$2.invokeSuspend(RunningThreadStackMergeTest.kt:77)\n" +
+ "\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest.suspendingFunction(RunningThreadStackMergeTest.kt:75)\n" +
+ "\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest\$launchCoroutine\$1.invokeSuspend(RunningThreadStackMergeTest.kt:68)\n" +
+ "\t(Coroutine creation stacktrace)\n" +
+ "\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)",
+ ignoredCoroutine = "BlockingCoroutine"
+ )
+ coroutineBlocker.await()
+ }
+
+ private fun awaitCoroutineStarted() {
+ testMainBlocker.await()
+ while (coroutineBlocker.numberWaiting != 1) {
+ Thread.sleep(10)
+ }
+ }
+
+ private fun CoroutineScope.launchCoroutine() {
+ launch(Dispatchers.Default) {
+ suspendingFunction()
+ assertTrue(true)
+ }
+ }
+
+ private suspend fun suspendingFunction() {
+ // Typical use-case
+ withContext(Dispatchers.IO) {
+ yield()
+ nonSuspendingFun()
+ }
+
+ assertTrue(true)
+ }
+
+ private fun nonSuspendingFun() {
+ testMainBlocker.countDown()
+ coroutineBlocker.await()
+ }
+
+ @Test
+ fun testStackMergeEscapeSuspendMethod() = runTest {
+ launchEscapingCoroutine()
+ awaitCoroutineStarted()
+ verifyDump(
+ "Coroutine \"coroutine#1\":BlockingCoroutine{Active}@62230679", // <- this one is ignored
+ "Coroutine \"coroutine#2\":StandaloneCoroutine{Active}@3aea3c67, state: RUNNING\n" +
+ "\tat sun.misc.Unsafe.park(Native Method)\n" +
+ "\tat java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)\n" +
+ "\tat java.util.concurrent.locks.AbstractQueuedSynchronizer\$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)\n" +
+ "\tat java.util.concurrent.CyclicBarrier.dowait(CyclicBarrier.java:234)\n" +
+ "\tat java.util.concurrent.CyclicBarrier.await(CyclicBarrier.java:362)\n" +
+ "\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest.nonSuspendingFun(RunningThreadStackMergeTest.kt:83)\n" +
+ "\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest.access\$nonSuspendingFun(RunningThreadStackMergeTest.kt:12)\n" +
+ "\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest\$suspendingFunctionWithContext\$2.invokeSuspend(RunningThreadStackMergeTest.kt:124)\n" +
+ "\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest.suspendingFunctionWithContext(RunningThreadStackMergeTest.kt:122)\n" +
+ "\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest\$launchEscapingCoroutine\$1.invokeSuspend(RunningThreadStackMergeTest.kt:116)\n" +
+ "\t(Coroutine creation stacktrace)\n" +
+ "\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)",
+ ignoredCoroutine = "BlockingCoroutine"
+ )
+ coroutineBlocker.await()
+ }
+
+ @Test
+ fun testRunBlocking() = runBlocking {
+ verifyDump("Coroutine \"coroutine#1\":BlockingCoroutine{Active}@4bcd176c, state: RUNNING\n" +
+ "\tat java.lang.Thread.getStackTrace(Thread.java:1552)\n" +
+ "\tat kotlinx.coroutines.debug.internal.DebugProbesImpl.enhanceStackTraceWithThreadDump(DebugProbesImpl.kt:147)\n" +
+ "\tat kotlinx.coroutines.debug.internal.DebugProbesImpl.dumpCoroutines(DebugProbesImpl.kt:122)\n" +
+ "\tat kotlinx.coroutines.debug.internal.DebugProbesImpl.dumpCoroutines(DebugProbesImpl.kt:109)\n" +
+ "\tat kotlinx.coroutines.debug.DebugProbes.dumpCoroutines(DebugProbes.kt:122)\n" +
+ "\tat kotlinx.coroutines.debug.StracktraceUtilsKt.verifyDump(StracktraceUtils.kt)\n" +
+ "\tat kotlinx.coroutines.debug.StracktraceUtilsKt.verifyDump\$default(StracktraceUtils.kt)\n" +
+ "\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest\$testRunBlocking\$1.invokeSuspend(RunningThreadStackMergeTest.kt:112)\n" +
+ "\t(Coroutine creation stacktrace)\n" +
+ "\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n")
+ }
+
+ private fun CoroutineScope.launchEscapingCoroutine() {
+ launch(Dispatchers.Default) {
+ suspendingFunctionWithContext()
+ assertTrue(true)
+ }
+ }
+
+ private suspend fun suspendingFunctionWithContext() {
+ withContext(Dispatchers.IO) {
+ actualSuspensionPoint()
+ nonSuspendingFun()
+ }
+
+ assertTrue(true)
+ }
+
+ private suspend fun actualSuspensionPoint() {
+ nestedSuspensionPoint()
+ assertTrue(true)
+ }
+
+ private suspend fun nestedSuspensionPoint() {
+ yield()
+ assertTrue(true)
+ }
+}
diff --git a/kotlinx-coroutines-debug/test/SanitizedProbesTest.kt b/kotlinx-coroutines-debug/test/SanitizedProbesTest.kt
index 1eb8157..4d35d02 100644
--- a/kotlinx-coroutines-debug/test/SanitizedProbesTest.kt
+++ b/kotlinx-coroutines-debug/test/SanitizedProbesTest.kt
@@ -59,8 +59,8 @@
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" +
+ "Coroutine \"coroutine#3\":BlockingCoroutine{Active}@7d68ef40, state: RUNNING\n" +
+ "\tat java.lang.Thread.getStackTrace(Thread.java)\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" +
@@ -90,7 +90,8 @@
expect(1)
yield()
expect(3)
- verifyDump("Coroutine \"coroutine#1\":BlockingCoroutine{Active}@35fc6dc4, state: RUNNING (Last suspension stacktrace, not an actual stacktrace)\n" +
+ verifyDump("Coroutine \"coroutine#1\":BlockingCoroutine{Active}@35fc6dc4, state: RUNNING\n" +
+ "\tat java.lang.Thread.getStackTrace(Thread.java:1552)\n" + // Skip the rest
"\t(Coroutine creation stacktrace)\n" +
"\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)",
@@ -121,7 +122,6 @@
delay(Long.MAX_VALUE)
1
}
-
}
}
}
diff --git a/kotlinx-coroutines-debug/test/ScopedBuildersTest.kt b/kotlinx-coroutines-debug/test/ScopedBuildersTest.kt
index d0657d7..25b4633 100644
--- a/kotlinx-coroutines-debug/test/ScopedBuildersTest.kt
+++ b/kotlinx-coroutines-debug/test/ScopedBuildersTest.kt
@@ -31,10 +31,9 @@
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" +
+ "Coroutine \"coroutine#1\":BlockingCoroutine{Active}@16612a51, state: RUNNING\n" +
"\t(Coroutine creation stacktrace)\n" +
- "\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\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" +
@@ -61,4 +60,4 @@
}
expectUnreached()
}
-}
\ No newline at end of file
+}
diff --git a/kotlinx-coroutines-debug/test/StracktraceUtils.kt b/kotlinx-coroutines-debug/test/StracktraceUtils.kt
index baa48b0..62dcd78 100644
--- a/kotlinx-coroutines-debug/test/StracktraceUtils.kt
+++ b/kotlinx-coroutines-debug/test/StracktraceUtils.kt
@@ -55,7 +55,7 @@
public fun String.count(substring: String): Int = split(substring).size - 1
-public fun verifyDump(vararg traces: String) {
+public fun verifyDump(vararg traces: String, ignoredCoroutine: String? = null) {
val baos = ByteArrayOutputStream()
DebugProbes.dumpCoroutines(PrintStream(baos))
val trace = baos.toString().split("\n\n")
@@ -66,6 +66,10 @@
}
// Drop "Coroutine dump" line
trace.withIndex().drop(1).forEach { (index, value) ->
+ if (ignoredCoroutine != null && value.contains(ignoredCoroutine)) {
+ return@forEach
+ }
+
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)