Skip to content

Commit f18878f

Browse files
qwwdfsadqwwdfsad
authored
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
1 parent 688aca4 commit f18878f

File tree

6 files changed

+242
-14
lines changed

6 files changed

+242
-14
lines changed

‎kotlinx-coroutines-debug/src/CoroutineState.kt

Lines changed: 10 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -39,6 +39,9 @@ public data class CoroutineState internal constructor(
3939

4040
private var _state: State = State.CREATED
4141

42+
@JvmField
43+
internal var lastObservedThread: Thread? = null
44+
4245
private var lastObservedFrame: CoroutineStackFrame? = null
4346

4447
// Copy constructor
@@ -66,9 +69,15 @@ public data class CoroutineState internal constructor(
6669
}
6770

6871
internal fun updateState(state: State, frame: Continuation<*>) {
69-
if (_state == state && lastObservedFrame != null) return
72+
// Propagate only duplicating transitions to running for KT-29997
73+
if (_state == state && state == State.SUSPENDED && lastObservedFrame != null) return
7074
_state = state
7175
lastObservedFrame = frame as? CoroutineStackFrame
76+
if (state == State.RUNNING) {
77+
lastObservedThread = Thread.currentThread()
78+
} else {
79+
lastObservedThread = null
80+
}
7281
}
7382

7483
/**
@@ -83,7 +92,6 @@ public data class CoroutineState internal constructor(
8392
frame.getStackTraceElement()?.let { result.add(sanitize(it)) }
8493
frame = frame.callerFrame
8594
}
86-
8795
return result
8896
}
8997
}

‎kotlinx-coroutines-debug/src/internal/DebugProbesImpl.kt

Lines changed: 70 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -117,22 +117,89 @@ internal object DebugProbesImpl {
117117
.asSequence()
118118
.sortedBy { it.value.sequenceNumber }
119119
.forEach { (key, value) ->
120-
val state = if (value.state == State.RUNNING)
120+
val observedStackTrace = value.lastObservedStackTrace()
121+
val enhancedStackTrace = enhanceStackTraceWithThreadDump(value, observedStackTrace)
122+
val state = if (value.state == State.RUNNING && enhancedStackTrace === observedStackTrace)
121123
"${value.state} (Last suspension stacktrace, not an actual stacktrace)"
122124
else
123125
value.state.toString()
124126

125127
append("\n\nCoroutine $key, state: $state")
126-
val observedStackTrace = value.lastObservedStackTrace()
127128
if (observedStackTrace.isEmpty()) {
128129
append("\n\tat ${artificialFrame(ARTIFICIAL_FRAME_MESSAGE)}")
129130
printStackTrace(value.creationStackTrace)
130131
} else {
131-
printStackTrace(value.lastObservedStackTrace())
132+
printStackTrace(enhancedStackTrace)
132133
}
133134
}
134135
}
135136

137+
/**
138+
* Tries to enhance [coroutineTrace] (obtained by call to [CoroutineState.lastObservedStackTrace]) with
139+
* thread dump of [CoroutineState.lastObservedThread].
140+
*
141+
* Returns [coroutineTrace] if enhancement was unsuccessful or the enhancement result.
142+
*/
143+
private fun enhanceStackTraceWithThreadDump(
144+
state: CoroutineState,
145+
coroutineTrace: List<StackTraceElement>
146+
): List<StackTraceElement> {
147+
val thread = state.lastObservedThread
148+
if (state.state != State.RUNNING || thread == null) return coroutineTrace
149+
// Avoid security manager issues
150+
val actualTrace = runCatching { thread.stackTrace }.getOrNull()
151+
?: return coroutineTrace
152+
153+
/*
154+
* Here goes heuristic that tries to merge two stacktraces: real one
155+
* (that has at least one but usually not so many suspend function frames)
156+
* and coroutine one that has only suspend function frames.
157+
*
158+
* Heuristic:
159+
* 1) Dump lastObservedThread
160+
* 2) Find the next frame after BaseContinuationImpl.resumeWith (continuation machinery).
161+
* Invariant: this method is called under the lock, so such method **should** be present
162+
* in continuation stacktrace.
163+
*
164+
* 3) Find target method in continuation stacktrace (metadata-based)
165+
* 4) Prepend dumped stacktrace (trimmed by target frame) to continuation stacktrace
166+
*
167+
* Heuristic may fail on recursion and overloads, but it will be automatically improved
168+
* with KT-29997
169+
*/
170+
val indexOfResumeWith = actualTrace.indexOfFirst {
171+
it.className == "kotlin.coroutines.jvm.internal.BaseContinuationImpl" &&
172+
it.methodName == "resumeWith" &&
173+
it.fileName == "ContinuationImpl.kt"
174+
}
175+
176+
// We haven't found "BaseContinuationImpl.resumeWith" resume call in stacktrace
177+
// This is some inconsistency in machinery, do not fail, fallback
178+
val continuationFrame = actualTrace.getOrNull(indexOfResumeWith - 1)
179+
?: return coroutineTrace
180+
181+
val continuationStartFrame = coroutineTrace.indexOfFirst {
182+
it.fileName == continuationFrame.fileName &&
183+
it.className == continuationFrame.className &&
184+
it.methodName == continuationFrame.methodName
185+
} + 1
186+
187+
if (continuationStartFrame == 0) return coroutineTrace
188+
189+
val expectedSize = indexOfResumeWith + coroutineTrace.size - continuationStartFrame
190+
val result = ArrayList<StackTraceElement>(expectedSize)
191+
192+
for (index in 0 until indexOfResumeWith) {
193+
result += actualTrace[index]
194+
}
195+
196+
for (index in continuationStartFrame until coroutineTrace.size) {
197+
result += coroutineTrace[index]
198+
}
199+
200+
return result
201+
}
202+
136203
private fun StringBuilder.printStackTrace(frames: List<StackTraceElement>) {
137204
frames.forEach { frame ->
138205
append("\n\tat $frame")

‎kotlinx-coroutines-debug/test/RunningThreadStackMergeTest.kt

Lines changed: 150 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,150 @@
1+
/*
2+
* Copyright 2016-2019 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license.
3+
*/
4+
package kotlinx.coroutines.debug
5+
6+
import kotlinx.coroutines.*
7+
import org.junit.*
8+
import org.junit.Test
9+
import java.util.concurrent.*
10+
import kotlin.test.*
11+
12+
class RunningThreadStackMergeTest : TestBase() {
13+
14+
private val testMainBlocker = CountDownLatch(1) // Test body blocks on it
15+
private val coroutineBlocker = CyclicBarrier(2) // Launched coroutine blocks on it
16+
17+
@Before
18+
fun setUp() {
19+
before()
20+
DebugProbes.install()
21+
}
22+
23+
@After
24+
fun tearDown() {
25+
try {
26+
DebugProbes.uninstall()
27+
} finally {
28+
onCompletion()
29+
}
30+
}
31+
32+
@Test
33+
fun testStackMergeWithContext() = runTest {
34+
launchCoroutine()
35+
awaitCoroutineStarted()
36+
37+
verifyDump(
38+
"Coroutine \"coroutine#1\":BlockingCoroutine{Active}@62230679", // <- this one is ignored
39+
"Coroutine \"coroutine#2\":StandaloneCoroutine{Active}@50284dc4, state: RUNNING\n" +
40+
"\tat sun.misc.Unsafe.park(Native Method)\n" +
41+
"\tat java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)\n" +
42+
"\tat java.util.concurrent.locks.AbstractQueuedSynchronizer\$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)\n" +
43+
"\tat java.util.concurrent.CyclicBarrier.dowait(CyclicBarrier.java:234)\n" +
44+
"\tat java.util.concurrent.CyclicBarrier.await(CyclicBarrier.java:362)\n" +
45+
"\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest.nonSuspendingFun(RunningThreadStackMergeTest.kt:86)\n" +
46+
"\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest.access\$nonSuspendingFun(RunningThreadStackMergeTest.kt:12)\n" +
47+
"\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest\$suspendingFunction\$2.invokeSuspend(RunningThreadStackMergeTest.kt:77)\n" +
48+
"\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest.suspendingFunction(RunningThreadStackMergeTest.kt:75)\n" +
49+
"\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest\$launchCoroutine\$1.invokeSuspend(RunningThreadStackMergeTest.kt:68)\n" +
50+
"\t(Coroutine creation stacktrace)\n" +
51+
"\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)",
52+
ignoredCoroutine = "BlockingCoroutine"
53+
)
54+
coroutineBlocker.await()
55+
}
56+
57+
private fun awaitCoroutineStarted() {
58+
testMainBlocker.await()
59+
while (coroutineBlocker.numberWaiting != 1) {
60+
Thread.sleep(10)
61+
}
62+
}
63+
64+
private fun CoroutineScope.launchCoroutine() {
65+
launch(Dispatchers.Default) {
66+
suspendingFunction()
67+
assertTrue(true)
68+
}
69+
}
70+
71+
private suspend fun suspendingFunction() {
72+
// Typical use-case
73+
withContext(Dispatchers.IO) {
74+
yield()
75+
nonSuspendingFun()
76+
}
77+
78+
assertTrue(true)
79+
}
80+
81+
private fun nonSuspendingFun() {
82+
testMainBlocker.countDown()
83+
coroutineBlocker.await()
84+
}
85+
86+
@Test
87+
fun testStackMergeEscapeSuspendMethod() = runTest {
88+
launchEscapingCoroutine()
89+
awaitCoroutineStarted()
90+
verifyDump(
91+
"Coroutine \"coroutine#1\":BlockingCoroutine{Active}@62230679", // <- this one is ignored
92+
"Coroutine \"coroutine#2\":StandaloneCoroutine{Active}@3aea3c67, state: RUNNING\n" +
93+
"\tat sun.misc.Unsafe.park(Native Method)\n" +
94+
"\tat java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)\n" +
95+
"\tat java.util.concurrent.locks.AbstractQueuedSynchronizer\$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)\n" +
96+
"\tat java.util.concurrent.CyclicBarrier.dowait(CyclicBarrier.java:234)\n" +
97+
"\tat java.util.concurrent.CyclicBarrier.await(CyclicBarrier.java:362)\n" +
98+
"\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest.nonSuspendingFun(RunningThreadStackMergeTest.kt:83)\n" +
99+
"\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest.access\$nonSuspendingFun(RunningThreadStackMergeTest.kt:12)\n" +
100+
"\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest\$suspendingFunctionWithContext\$2.invokeSuspend(RunningThreadStackMergeTest.kt:124)\n" +
101+
"\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest.suspendingFunctionWithContext(RunningThreadStackMergeTest.kt:122)\n" +
102+
"\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest\$launchEscapingCoroutine\$1.invokeSuspend(RunningThreadStackMergeTest.kt:116)\n" +
103+
"\t(Coroutine creation stacktrace)\n" +
104+
"\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)",
105+
ignoredCoroutine = "BlockingCoroutine"
106+
)
107+
coroutineBlocker.await()
108+
}
109+
110+
@Test
111+
fun testRunBlocking() = runBlocking {
112+
verifyDump("Coroutine \"coroutine#1\":BlockingCoroutine{Active}@4bcd176c, state: RUNNING\n" +
113+
"\tat java.lang.Thread.getStackTrace(Thread.java:1552)\n" +
114+
"\tat kotlinx.coroutines.debug.internal.DebugProbesImpl.enhanceStackTraceWithThreadDump(DebugProbesImpl.kt:147)\n" +
115+
"\tat kotlinx.coroutines.debug.internal.DebugProbesImpl.dumpCoroutines(DebugProbesImpl.kt:122)\n" +
116+
"\tat kotlinx.coroutines.debug.internal.DebugProbesImpl.dumpCoroutines(DebugProbesImpl.kt:109)\n" +
117+
"\tat kotlinx.coroutines.debug.DebugProbes.dumpCoroutines(DebugProbes.kt:122)\n" +
118+
"\tat kotlinx.coroutines.debug.StracktraceUtilsKt.verifyDump(StracktraceUtils.kt)\n" +
119+
"\tat kotlinx.coroutines.debug.StracktraceUtilsKt.verifyDump\$default(StracktraceUtils.kt)\n" +
120+
"\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest\$testRunBlocking\$1.invokeSuspend(RunningThreadStackMergeTest.kt:112)\n" +
121+
"\t(Coroutine creation stacktrace)\n" +
122+
"\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n")
123+
}
124+
125+
private fun CoroutineScope.launchEscapingCoroutine() {
126+
launch(Dispatchers.Default) {
127+
suspendingFunctionWithContext()
128+
assertTrue(true)
129+
}
130+
}
131+
132+
private suspend fun suspendingFunctionWithContext() {
133+
withContext(Dispatchers.IO) {
134+
actualSuspensionPoint()
135+
nonSuspendingFun()
136+
}
137+
138+
assertTrue(true)
139+
}
140+
141+
private suspend fun actualSuspensionPoint() {
142+
nestedSuspensionPoint()
143+
assertTrue(true)
144+
}
145+
146+
private suspend fun nestedSuspensionPoint() {
147+
yield()
148+
assertTrue(true)
149+
}
150+
}

‎kotlinx-coroutines-debug/test/SanitizedProbesTest.kt

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -59,8 +59,8 @@ class SanitizedProbesTest : TestBase() {
5959
val deferred = createActiveDeferred()
6060
yield()
6161
verifyDump(
62-
"Coroutine \"coroutine#3\":BlockingCoroutine{Active}@7d68ef40, state: RUNNING (Last suspension stacktrace, not an actual stacktrace)\n" +
63-
"\tat definitely.not.kotlinx.coroutines.SanitizedProbesTest\$testCoroutinesDump\$1.invokeSuspend(SanitizedProbesTest.kt:58)\n" +
62+
"Coroutine \"coroutine#3\":BlockingCoroutine{Active}@7d68ef40, state: RUNNING\n" +
63+
"\tat java.lang.Thread.getStackTrace(Thread.java)\n" +
6464
"\t(Coroutine creation stacktrace)\n" +
6565
"\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n" +
6666
"\tat kotlinx.coroutines.intrinsics.CancellableKt.startCoroutineCancellable(Cancellable.kt:23)\n" +
@@ -90,7 +90,8 @@ class SanitizedProbesTest : TestBase() {
9090
expect(1)
9191
yield()
9292
expect(3)
93-
verifyDump("Coroutine \"coroutine#1\":BlockingCoroutine{Active}@35fc6dc4, state: RUNNING (Last suspension stacktrace, not an actual stacktrace)\n" +
93+
verifyDump("Coroutine \"coroutine#1\":BlockingCoroutine{Active}@35fc6dc4, state: RUNNING\n" +
94+
"\tat java.lang.Thread.getStackTrace(Thread.java:1552)\n" + // Skip the rest
9495
"\t(Coroutine creation stacktrace)\n" +
9596
"\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)",
9697

@@ -121,7 +122,6 @@ class SanitizedProbesTest : TestBase() {
121122
delay(Long.MAX_VALUE)
122123
1
123124
}
124-
125125
}
126126
}
127127
}

‎kotlinx-coroutines-debug/test/ScopedBuildersTest.kt

Lines changed: 3 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -31,10 +31,9 @@ class ScopedBuildersTest : TestBase() {
3131
yield()
3232
yield()
3333
verifyDump(
34-
"Coroutine \"coroutine#1\":BlockingCoroutine{Active}@16612a51, state: RUNNING (Last suspension stacktrace, not an actual stacktrace)\n" +
35-
"\tat kotlinx.coroutines.debug.ScopedBuildersTest\$testNestedScopes\$1.invokeSuspend(ScopedBuildersTest.kt:32)\n" +
34+
"Coroutine \"coroutine#1\":BlockingCoroutine{Active}@16612a51, state: RUNNING\n" +
3635
"\t(Coroutine creation stacktrace)\n" +
37-
"\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n",
36+
"\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n",
3837

3938
"Coroutine \"coroutine#2\":StandaloneCoroutine{Active}@6b53e23f, state: SUSPENDED\n" +
4039
"\tat kotlinx.coroutines.debug.ScopedBuildersTest\$doWithContext\$2.invokeSuspend(ScopedBuildersTest.kt:49)\n" +
@@ -61,4 +60,4 @@ class ScopedBuildersTest : TestBase() {
6160
}
6261
expectUnreached()
6362
}
64-
}
63+
}

‎kotlinx-coroutines-debug/test/StracktraceUtils.kt

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -55,7 +55,7 @@ public fun toStackTrace(t: Throwable): String {
5555

5656
public fun String.count(substring: String): Int = split(substring).size - 1
5757

58-
public fun verifyDump(vararg traces: String) {
58+
public fun verifyDump(vararg traces: String, ignoredCoroutine: String? = null) {
5959
val baos = ByteArrayOutputStream()
6060
DebugProbes.dumpCoroutines(PrintStream(baos))
6161
val trace = baos.toString().split("\n\n")
@@ -66,6 +66,10 @@ public fun verifyDump(vararg traces: String) {
6666
}
6767
// Drop "Coroutine dump" line
6868
trace.withIndex().drop(1).forEach { (index, value) ->
69+
if (ignoredCoroutine != null && value.contains(ignoredCoroutine)) {
70+
return@forEach
71+
}
72+
6973
val expected = traces[index - 1].applyBackspace().split("\n\t(Coroutine creation stacktrace)\n", limit = 2)
7074
val actual = value.applyBackspace().split("\n\t(Coroutine creation stacktrace)\n", limit = 2)
7175
assertEquals(expected.size, actual.size)

0 commit comments

Comments
 (0)