Skip to content

Commit ffaedf1

Browse files
qwwdfsadqwwdfsad
committed
Improve stacktrace merge heuristic: skip state machine meaningless frame when attempting to merge stacktraces
Use timeout in all tests
1 parent ab5bbfc commit ffaedf1

7 files changed

+144
-120
lines changed

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

+48-20
Original file line numberDiff line numberDiff line change
@@ -6,7 +6,6 @@ package kotlinx.coroutines.debug.internal
66

77
import kotlinx.coroutines.*
88
import kotlinx.coroutines.debug.*
9-
import kotlinx.coroutines.internal.artificialFrame
109
import net.bytebuddy.*
1110
import net.bytebuddy.agent.*
1211
import net.bytebuddy.dynamic.loading.*
@@ -16,6 +15,7 @@ import java.util.*
1615
import kotlin.collections.ArrayList
1716
import kotlin.coroutines.*
1817
import kotlin.coroutines.jvm.internal.*
18+
import kotlinx.coroutines.internal.artificialFrame as createArtificialFrame // IDEA bug workaround
1919

2020
/**
2121
* Mirror of [DebugProbes] with actual implementation.
@@ -134,7 +134,7 @@ internal object DebugProbesImpl {
134134

135135
append("\n\nCoroutine $key, state: $state")
136136
if (observedStackTrace.isEmpty()) {
137-
append("\n\tat ${artificialFrame(ARTIFICIAL_FRAME_MESSAGE)}")
137+
append("\n\tat ${createArtificialFrame(ARTIFICIAL_FRAME_MESSAGE)}")
138138
printStackTrace(value.creationStackTrace)
139139
} else {
140140
printStackTrace(enhancedStackTrace)
@@ -168,7 +168,6 @@ internal object DebugProbesImpl {
168168
* 2) Find the next frame after BaseContinuationImpl.resumeWith (continuation machinery).
169169
* Invariant: this method is called under the lock, so such method **should** be present
170170
* in continuation stacktrace.
171-
*
172171
* 3) Find target method in continuation stacktrace (metadata-based)
173172
* 4) Prepend dumped stacktrace (trimmed by target frame) to continuation stacktrace
174173
*
@@ -181,33 +180,62 @@ internal object DebugProbesImpl {
181180
it.fileName == "ContinuationImpl.kt"
182181
}
183182

184-
// We haven't found "BaseContinuationImpl.resumeWith" resume call in stacktrace
185-
// This is some inconsistency in machinery, do not fail, fallback
186-
val continuationFrame = actualTrace.getOrNull(indexOfResumeWith - 1)
187-
?: return coroutineTrace
188-
189-
val continuationStartFrame = coroutineTrace.indexOfFirst {
190-
it.fileName == continuationFrame.fileName &&
191-
it.className == continuationFrame.className &&
192-
it.methodName == continuationFrame.methodName
193-
} + 1
183+
val (continuationStartFrame, frameSkipped) = findContinuationStartIndex(
184+
indexOfResumeWith,
185+
actualTrace,
186+
coroutineTrace)
194187

195-
if (continuationStartFrame == 0) return coroutineTrace
188+
if (continuationStartFrame == -1) return coroutineTrace
196189

197-
val expectedSize = indexOfResumeWith + coroutineTrace.size - continuationStartFrame
190+
val delta = if (frameSkipped) 1 else 0
191+
val expectedSize = indexOfResumeWith + coroutineTrace.size - continuationStartFrame - 1 - delta
198192
val result = ArrayList<StackTraceElement>(expectedSize)
199-
200-
for (index in 0 until indexOfResumeWith) {
193+
for (index in 0 until indexOfResumeWith - delta) {
201194
result += actualTrace[index]
202195
}
203196

204-
for (index in continuationStartFrame until coroutineTrace.size) {
197+
for (index in continuationStartFrame + 1 until coroutineTrace.size) {
205198
result += coroutineTrace[index]
206199
}
207200

208201
return result
209202
}
210203

204+
/**
205+
* Tries to find the lowest meaningful frame above `resumeWith` in the real stacktrace and
206+
* its match in a coroutines stacktrace (steps 2-3 in heuristic).
207+
*
208+
* This method does more than just matching `realTrace.indexOf(resumeWith) - 1`:
209+
* If method above `resumeWith` has no line number (thus it is `stateMachine.invokeSuspend`),
210+
* it's skipped and attempt to match next one is made because state machine could have been missing in the original coroutine stacktrace.
211+
*
212+
* Returns index of such frame (or -1) and flag indicating whether frame with state machine was skipped
213+
*/
214+
private fun findContinuationStartIndex(
215+
indexOfResumeWith: Int,
216+
actualTrace: Array<StackTraceElement>,
217+
coroutineTrace: List<StackTraceElement>
218+
): Pair<Int, Boolean> {
219+
val result = findIndexOfFrame(indexOfResumeWith - 1, actualTrace, coroutineTrace)
220+
if (result == -1) return findIndexOfFrame(indexOfResumeWith - 2, actualTrace, coroutineTrace) to true
221+
return result to false
222+
}
223+
224+
private fun findIndexOfFrame(
225+
frameIndex: Int,
226+
actualTrace: Array<StackTraceElement>,
227+
coroutineTrace: List<StackTraceElement>
228+
): Int {
229+
val continuationFrame = actualTrace.getOrNull(frameIndex)
230+
?: return -1
231+
232+
return coroutineTrace.indexOfFirst {
233+
it.fileName == continuationFrame.fileName &&
234+
it.className == continuationFrame.className &&
235+
it.methodName == continuationFrame.methodName
236+
}
237+
}
238+
211239
private fun StringBuilder.printStackTrace(frames: List<StackTraceElement>) {
212240
frames.forEach { frame ->
213241
append("\n\tat $frame")
@@ -292,7 +320,7 @@ internal object DebugProbesImpl {
292320

293321
if (!DebugProbes.sanitizeStackTraces) {
294322
return List(size - probeIndex) {
295-
if (it == 0) artificialFrame(ARTIFICIAL_FRAME_MESSAGE) else stackTrace[it + probeIndex]
323+
if (it == 0) createArtificialFrame(ARTIFICIAL_FRAME_MESSAGE) else stackTrace[it + probeIndex]
296324
}
297325
}
298326

@@ -302,7 +330,7 @@ internal object DebugProbesImpl {
302330
* output will be [e, i1, i3, e, i4, e, i5, i7]
303331
*/
304332
val result = ArrayList<StackTraceElement>(size - probeIndex + 1)
305-
result += artificialFrame(ARTIFICIAL_FRAME_MESSAGE)
333+
result += createArtificialFrame(ARTIFICIAL_FRAME_MESSAGE)
306334
var includeInternalFrame = true
307335
for (i in (probeIndex + 1) until size - 1) {
308336
val element = stackTrace[i]

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

+5-20
Original file line numberDiff line numberDiff line change
@@ -5,32 +5,15 @@
55
package kotlinx.coroutines.debug
66

77
import kotlinx.coroutines.*
8+
import kotlinx.coroutines.debug.junit4.*
89
import org.junit.*
910
import org.junit.Test
1011
import kotlin.coroutines.*
1112
import kotlin.test.*
1213

13-
@Suppress("SUSPENSION_POINT_INSIDE_MONITOR") // bug in 1.3.0 FE
14-
class CoroutinesDumpTest : TestBase() {
15-
14+
class CoroutinesDumpTest : DebugTestBase() {
1615
private val monitor = Any()
1716

18-
@Before
19-
fun setUp() {
20-
before()
21-
DebugProbes.sanitizeStackTraces = false
22-
DebugProbes.install()
23-
}
24-
25-
@After
26-
fun tearDown() {
27-
try {
28-
DebugProbes.uninstall()
29-
} finally {
30-
onCompletion()
31-
}
32-
}
33-
3417
@Test
3518
fun testSuspendedCoroutine() = synchronized(monitor) {
3619
val deferred = GlobalScope.async {
@@ -85,8 +68,10 @@ class CoroutinesDumpTest : TestBase() {
8568
}
8669

8770
awaitCoroutineStarted()
71+
Thread.sleep(10)
8872
verifyDump(
89-
"Coroutine \"coroutine#1\":DeferredCoroutine{Active}@1e4a7dd4, state: RUNNING (Last suspension stacktrace, not an actual stacktrace)\n" +
73+
"Coroutine \"coroutine#1\":DeferredCoroutine{Active}@1e4a7dd4, state: RUNNING\n" +
74+
"\tat java.lang.Thread.sleep(Native Method)\n" +
9075
"\tat kotlinx.coroutines.debug.CoroutinesDumpTest.nestedActiveMethod(CoroutinesDumpTest.kt:111)\n" +
9176
"\tat kotlinx.coroutines.debug.CoroutinesDumpTest.activeMethod(CoroutinesDumpTest.kt:106)\n" +
9277
"\tat kotlinx.coroutines.debug.CoroutinesDumpTest\$testRunningCoroutineWithSuspensionPoint\$1\$deferred\$1.invokeSuspend(CoroutinesDumpTest.kt:71)\n" +

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

+32
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,32 @@
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+
7+
import kotlinx.coroutines.*
8+
import kotlinx.coroutines.debug.junit4.*
9+
import org.junit.*
10+
11+
open class DebugTestBase : TestBase() {
12+
13+
@JvmField
14+
@Rule
15+
val timeout = CoroutinesTimeout.seconds(10)
16+
17+
@Before
18+
open fun setUp() {
19+
before()
20+
DebugProbes.sanitizeStackTraces = false
21+
DebugProbes.install()
22+
}
23+
24+
@After
25+
fun tearDown() {
26+
try {
27+
DebugProbes.uninstall()
28+
} finally {
29+
onCompletion()
30+
}
31+
}
32+
}

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

+54-34
Original file line numberDiff line numberDiff line change
@@ -4,31 +4,15 @@
44
package kotlinx.coroutines.debug
55

66
import kotlinx.coroutines.*
7-
import org.junit.*
87
import org.junit.Test
98
import java.util.concurrent.*
109
import kotlin.test.*
1110

12-
class RunningThreadStackMergeTest : TestBase() {
11+
class RunningThreadStackMergeTest : DebugTestBase() {
1312

1413
private val testMainBlocker = CountDownLatch(1) // Test body blocks on it
1514
private val coroutineBlocker = CyclicBarrier(2) // Launched coroutine blocks on it
1615

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-
3216
@Test
3317
fun testStackMergeWithContext() = runTest {
3418
launchCoroutine()
@@ -49,7 +33,7 @@ class RunningThreadStackMergeTest : TestBase() {
4933
"\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest\$launchCoroutine\$1.invokeSuspend(RunningThreadStackMergeTest.kt:68)\n" +
5034
"\t(Coroutine creation stacktrace)\n" +
5135
"\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)",
52-
ignoredCoroutine = "BlockingCoroutine"
36+
ignoredCoroutine = ":BlockingCoroutine"
5337
)
5438
coroutineBlocker.await()
5539
}
@@ -102,26 +86,11 @@ class RunningThreadStackMergeTest : TestBase() {
10286
"\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest\$launchEscapingCoroutine\$1.invokeSuspend(RunningThreadStackMergeTest.kt:116)\n" +
10387
"\t(Coroutine creation stacktrace)\n" +
10488
"\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)",
105-
ignoredCoroutine = "BlockingCoroutine"
89+
ignoredCoroutine = ":BlockingCoroutine"
10690
)
10791
coroutineBlocker.await()
10892
}
10993

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-
12594
private fun CoroutineScope.launchEscapingCoroutine() {
12695
launch(Dispatchers.Default) {
12796
suspendingFunctionWithContext()
@@ -138,6 +107,57 @@ class RunningThreadStackMergeTest : TestBase() {
138107
assertTrue(true)
139108
}
140109

110+
@Test
111+
fun testMergeThroughInvokeSuspend() = runTest {
112+
launchEscapingCoroutineWithoutContext()
113+
awaitCoroutineStarted()
114+
verifyDump(
115+
"Coroutine \"coroutine#1\":BlockingCoroutine{Active}@62230679", // <- this one is ignored
116+
"Coroutine \"coroutine#2\":StandaloneCoroutine{Active}@3aea3c67, state: RUNNING\n" +
117+
"\tat sun.misc.Unsafe.park(Native Method)\n" +
118+
"\tat java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)\n" +
119+
"\tat java.util.concurrent.locks.AbstractQueuedSynchronizer\$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)\n" +
120+
"\tat java.util.concurrent.CyclicBarrier.dowait(CyclicBarrier.java:234)\n" +
121+
"\tat java.util.concurrent.CyclicBarrier.await(CyclicBarrier.java:362)\n" +
122+
"\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest.nonSuspendingFun(RunningThreadStackMergeTest.kt:83)\n" +
123+
"\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest.suspendingFunctionWithoutContext(RunningThreadStackMergeTest.kt:160)\n" +
124+
"\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest\$launchEscapingCoroutineWithoutContext\$1.invokeSuspend(RunningThreadStackMergeTest.kt:153)\n" +
125+
"\t(Coroutine creation stacktrace)\n" +
126+
"\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)",
127+
ignoredCoroutine = ":BlockingCoroutine"
128+
)
129+
coroutineBlocker.await()
130+
}
131+
132+
private fun CoroutineScope.launchEscapingCoroutineWithoutContext() {
133+
launch(Dispatchers.Default) {
134+
suspendingFunctionWithoutContext()
135+
assertTrue(true)
136+
}
137+
}
138+
139+
private suspend fun suspendingFunctionWithoutContext() {
140+
actualSuspensionPoint()
141+
nonSuspendingFun()
142+
assertTrue(true)
143+
}
144+
145+
@Test
146+
fun testRunBlocking() = runBlocking {
147+
verifyDump("Coroutine \"coroutine#1\":BlockingCoroutine{Active}@4bcd176c, state: RUNNING\n" +
148+
"\tat java.lang.Thread.getStackTrace(Thread.java:1552)\n" +
149+
"\tat kotlinx.coroutines.debug.internal.DebugProbesImpl.enhanceStackTraceWithThreadDump(DebugProbesImpl.kt:147)\n" +
150+
"\tat kotlinx.coroutines.debug.internal.DebugProbesImpl.dumpCoroutines(DebugProbesImpl.kt:122)\n" +
151+
"\tat kotlinx.coroutines.debug.internal.DebugProbesImpl.dumpCoroutines(DebugProbesImpl.kt:109)\n" +
152+
"\tat kotlinx.coroutines.debug.DebugProbes.dumpCoroutines(DebugProbes.kt:122)\n" +
153+
"\tat kotlinx.coroutines.debug.StracktraceUtilsKt.verifyDump(StracktraceUtils.kt)\n" +
154+
"\tat kotlinx.coroutines.debug.StracktraceUtilsKt.verifyDump\$default(StracktraceUtils.kt)\n" +
155+
"\tat kotlinx.coroutines.debug.RunningThreadStackMergeTest\$testRunBlocking\$1.invokeSuspend(RunningThreadStackMergeTest.kt:112)\n" +
156+
"\t(Coroutine creation stacktrace)\n" +
157+
"\tat kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n")
158+
}
159+
160+
141161
private suspend fun actualSuspensionPoint() {
142162
nestedSuspensionPoint()
143163
assertTrue(true)

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

+3-13
Original file line numberDiff line numberDiff line change
@@ -13,21 +13,11 @@ import org.junit.Test
1313
import java.util.concurrent.*
1414
import kotlin.test.*
1515

16-
class SanitizedProbesTest : TestBase() {
16+
class SanitizedProbesTest : DebugTestBase() {
1717
@Before
18-
fun setUp() {
19-
before()
18+
override fun setUp() {
19+
super.setUp()
2020
DebugProbes.sanitizeStackTraces = true
21-
DebugProbes.install()
22-
}
23-
24-
@After
25-
fun tearDown() {
26-
try {
27-
DebugProbes.uninstall()
28-
} finally {
29-
onCompletion()
30-
}
3121
}
3222

3323
@Test

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

+1-16
Original file line numberDiff line numberDiff line change
@@ -8,22 +8,7 @@ import kotlinx.coroutines.*
88
import org.junit.*
99
import kotlin.coroutines.*
1010

11-
class ScopedBuildersTest : TestBase() {
12-
@Before
13-
fun setUp() {
14-
before()
15-
DebugProbes.sanitizeStackTraces = false
16-
DebugProbes.install()
17-
}
18-
19-
@After
20-
fun tearDown() {
21-
try {
22-
DebugProbes.uninstall()
23-
} finally {
24-
onCompletion()
25-
}
26-
}
11+
class ScopedBuildersTest : DebugTestBase() {
2712

2813
@Test
2914
fun testNestedScopes() = runBlocking {

0 commit comments

Comments
 (0)