Skip to content

Commit 5a80d2a

Browse files
qwwdfsadqwwdfsad
committed
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
1 parent 8e2428c commit 5a80d2a

File tree

5 files changed

+106
-66
lines changed

5 files changed

+106
-66
lines changed

‎binary-compatibility-validator/reference-public-api/kotlinx-coroutines-debug.txt

Lines changed: 2 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,8 +1,7 @@
11
public final class kotlinx/coroutines/debug/CoroutineState {
22
public final fun component1 ()Lkotlin/coroutines/Continuation;
3-
public final fun component2 ()Ljava/util/List;
4-
public final fun copy (Lkotlin/coroutines/Continuation;Ljava/util/List;J)Lkotlinx/coroutines/debug/CoroutineState;
5-
public static synthetic fun copy$default (Lkotlinx/coroutines/debug/CoroutineState;Lkotlin/coroutines/Continuation;Ljava/util/List;JILjava/lang/Object;)Lkotlinx/coroutines/debug/CoroutineState;
3+
public final fun copy (Lkotlin/coroutines/Continuation;Lkotlin/coroutines/jvm/internal/CoroutineStackFrame;J)Lkotlinx/coroutines/debug/CoroutineState;
4+
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;
65
public fun equals (Ljava/lang/Object;)Z
76
public final fun getContinuation ()Lkotlin/coroutines/Continuation;
87
public final fun getCreationStackTrace ()Ljava/util/List;

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

Lines changed: 23 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -16,7 +16,7 @@ import kotlin.coroutines.*
1616
@ExperimentalCoroutinesApi
1717
public data class CoroutineState internal constructor(
1818
public val continuation: Continuation<*>,
19-
public val creationStackTrace: List<StackTraceElement>,
19+
private val creationStackBottom: CoroutineStackFrame,
2020
@JvmField internal val sequenceNumber: Long
2121
) {
2222

@@ -32,23 +32,42 @@ public data class CoroutineState internal constructor(
3232
*/
3333
public val jobOrNull: Job? get() = continuation.context[Job]
3434

35+
/**
36+
* Creation stacktrace of coroutine
37+
*/
38+
public val creationStackTrace: List<StackTraceElement> get() = creationStackTrace()
39+
3540
/**
3641
* Last observed [state][State] of the coroutine.
3742
*/
3843
public val state: State get() = _state
3944

45+
private var _state: State = State.CREATED
46+
47+
private var lastObservedFrame: CoroutineStackFrame? = null
48+
4049
// Copy constructor
4150
internal constructor(coroutine: Continuation<*>, state: CoroutineState) : this(
4251
coroutine,
43-
state.creationStackTrace,
52+
state.creationStackBottom,
4453
state.sequenceNumber) {
4554
_state = state.state
4655
this.lastObservedFrame = state.lastObservedFrame
4756
}
4857

49-
private var _state: State = State.CREATED
58+
private fun creationStackTrace(): List<StackTraceElement> {
59+
// Skip "Coroutine creation stacktrace" frame
60+
return sequence<StackTraceElement> { yieldFrames(creationStackBottom.callerFrame) }.toList()
61+
}
5062

51-
private var lastObservedFrame: CoroutineStackFrame? = null
63+
private tailrec suspend fun SequenceScope<StackTraceElement>.yieldFrames(frame: CoroutineStackFrame?) {
64+
if (frame == null) return
65+
frame.getStackTraceElement()?.let { yield(it) }
66+
val caller = frame.callerFrame
67+
if (caller != null) {
68+
yieldFrames(caller)
69+
}
70+
}
5271

5372
internal fun updateState(state: State, frame: Continuation<*>) {
5473
if (_state == state && lastObservedFrame != null) return

‎core/kotlinx-coroutines-debug/src/debug/DebugProbes.kt

Lines changed: 9 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -16,8 +16,8 @@ import kotlin.coroutines.*
1616
/**
1717
* Debug probes support.
1818
*
19-
* Debug probes is a dynamic attach mechanism, which installs multiple hooks into [Continuation] machinery.
20-
* It slows down all coroutine-related code, but in return provides a lot of debug information, including
19+
* Debug probes is a dynamic attach mechanism which installs multiple hooks into coroutines machinery.
20+
* It slows down all coroutine-related code, but in return provides a lot of diagnostic information, including
2121
* asynchronous stack-traces and coroutine dumps (similar to [ThreadMXBean.dumpAllThreads] and `jstack` via [DebugProbes.dumpCoroutines].
2222
*
2323
* Installed hooks:
@@ -30,24 +30,20 @@ import kotlin.coroutines.*
3030
* * Every created coroutine is stored in a weak hash map, thus adding additional GC pressure.
3131
* * On every created coroutine, stacktrace of the current thread is dumped.
3232
* * On every `resume` and `suspend`, [WeakHashMap] is updated under a global lock.
33-
*
34-
* **WARNING: DO NOT USE DEBUG PROBES IN PRODUCTION ENVIRONMENT.**
3533
*/
3634
@ExperimentalCoroutinesApi
3735
public object DebugProbes {
3836

3937
/**
4038
* Whether coroutine creation stacktraces should be sanitized.
4139
* Sanitization removes all frames from `kotlinx.coroutines` package except
42-
* the first one and the last one to simplify user's diagnostic.
40+
* the first one and the last one to simplify diagnostic.
4341
*/
4442
public var sanitizeStackTraces: Boolean = true
4543

4644
/**
4745
* Installs a [DebugProbes] instead of no-op stdlib probes by redefining
4846
* debug probes class using the same class loader as one loaded [DebugProbes] class.
49-
*
50-
* **WARNING: DO NOT USE DEBUG PROBES IN PRODUCTION ENVIRONMENT**
5147
*/
5248
public fun install() {
5349
DebugProbesImpl.install()
@@ -62,8 +58,6 @@ public object DebugProbes {
6258

6359
/**
6460
* Invokes given block of code with installed debug probes and uninstall probes in the end.
65-
*
66-
* **WARNING: DO NOT USE DEBUG PROBES IN PRODUCTION ENVIRONMENT**
6761
*/
6862
public inline fun withDebugProbes(block: () -> Unit) {
6963
install()
@@ -81,22 +75,21 @@ public object DebugProbes {
8175
public fun hierarchyToString(job: Job): String = DebugProbesImpl.hierarchyToString(job)
8276

8377
/**
84-
* Prints [job] hierarchy representation from [hierarchyToString] to given [out].
78+
* Prints [job] hierarchy representation from [hierarchyToString] to the given [out].
8579
*/
8680
public fun printHierarchy(job: Job, out: PrintStream = System.out) =
8781
out.println(DebugProbesImpl.hierarchyToString(job))
8882

8983
/**
90-
* Returns all alive coroutine states.
91-
* Resulting collection represents a consistent snapshot of all alive coroutines at the moment of invocation.
84+
* Returns all existing coroutine states.
85+
* The resulting collection represents a consistent snapshot of all existing coroutines at the moment of invocation.
9286
*/
9387
public fun dumpCoroutinesState(): List<CoroutineState> = DebugProbesImpl.dumpCoroutinesState()
9488

9589
/**
96-
* Dumps all active coroutines into given output stream.
97-
* Resulting collection represents a consistent snapshot of all alive coroutines at the moment of invocation.
98-
* Output of this method is similar to `jstack` or full thread dump, so this method can and should be used as replacement to
99-
* "Dump threads" action
90+
* Dumps all active coroutines into the given output stream, providing a consistent snapshot of all existing coroutines at the moment of invocation.
91+
* The output of this method is similar to `jstack` or a full thread dump. It can be used as the replacement to
92+
* "Dump threads" action.
10093
*
10194
* Example of the output:
10295
* ```

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

Lines changed: 41 additions & 35 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@ internal object DebugProbesImpl {
2525
private const val ARTIFICIAL_FRAME_MESSAGE = "Coroutine creation stacktrace"
2626
private val dateFormat = SimpleDateFormat("yyyy/MM/dd HH:mm:ss")
2727
private val capturedCoroutines = WeakHashMap<ArtificialStackFrame<*>, CoroutineState>()
28+
@Volatile
2829
private var installations = 0
2930
private val isInstalled: Boolean get() = installations > 0
3031
// To sort coroutines by creation order, used as unique id
@@ -111,37 +112,39 @@ internal object DebugProbesImpl {
111112
.toList()
112113
}
113114

114-
@Synchronized
115115
public fun dumpCoroutines(out: PrintStream) {
116116
if (!isInstalled) {
117117
error("Debug probes are not installed")
118118
}
119119

120120
// Avoid inference with other out/err invocations
121-
val resultingString = buildString {
122-
append("Coroutines dump ${dateFormat.format(System.currentTimeMillis())}")
121+
val resultingString = dumpCoroutines()
122+
out.println(resultingString)
123+
}
123124

125+
@Synchronized
126+
private fun dumpCoroutines(): String {
127+
// Synchronization window can be reduce even more, but no need to do it here
128+
return buildString {
129+
append("Coroutines dump ${dateFormat.format(System.currentTimeMillis())}")
124130
capturedCoroutines
125131
.asSequence()
126132
.sortedBy { it.value.sequenceNumber }
127133
.forEach { (key, value) ->
128-
val state = if (value.state == State.RUNNING)
129-
"${value.state} (Last suspension stacktrace, not an actual stacktrace)"
130-
else value.state.toString()
131-
132-
append("\n\nCoroutine $key, state: $state")
133-
val observedStackTrace = value.lastObservedStackTrace()
134-
if (observedStackTrace.isEmpty()) {
135-
append("\n\tat ${artificialFrame(ARTIFICIAL_FRAME_MESSAGE)}")
136-
printStackTrace(value.creationStackTrace)
137-
} else {
138-
printStackTrace(value.lastObservedStackTrace())
134+
val state = if (value.state == State.RUNNING)
135+
"${value.state} (Last suspension stacktrace, not an actual stacktrace)"
136+
else value.state.toString()
137+
138+
append("\n\nCoroutine $key, state: $state")
139+
val observedStackTrace = value.lastObservedStackTrace()
140+
if (observedStackTrace.isEmpty()) {
141+
append("\n\tat ${artificialFrame(ARTIFICIAL_FRAME_MESSAGE)}")
142+
printStackTrace(value.creationStackTrace)
143+
} else {
144+
printStackTrace(value.lastObservedStackTrace())
145+
}
139146
}
140-
}
141147
}
142-
143-
// Move it out of synchronization?
144-
out.println(resultingString)
145148
}
146149

147150
private fun StringBuilder.printStackTrace(frames: List<StackTraceElement>) {
@@ -150,10 +153,8 @@ internal object DebugProbesImpl {
150153
}
151154
}
152155

153-
@Synchronized
154156
internal fun probeCoroutineResumed(frame: Continuation<*>) = updateState(frame, State.RUNNING)
155157

156-
@Synchronized
157158
internal fun probeCoroutineSuspended(frame: Continuation<*>) = updateState(frame, State.SUSPENDED)
158159

159160
private fun updateState(frame: Continuation<*>, state: State) {
@@ -163,6 +164,11 @@ internal object DebugProbesImpl {
163164

164165
// Find ArtificialStackFrame of the coroutine
165166
val owner = frame.owner()
167+
updateState(owner, frame, state)
168+
}
169+
170+
@Synchronized
171+
private fun updateState(owner: ArtificialStackFrame<*>?, frame: Continuation<*>, state: State) {
166172
val coroutineState = capturedCoroutines[owner]
167173
if (coroutineState == null) {
168174
warn(frame, state)
@@ -176,7 +182,6 @@ internal object DebugProbesImpl {
176182

177183
private tailrec fun CoroutineStackFrame.owner(): ArtificialStackFrame<*>? = if (this is ArtificialStackFrame<*>) this else callerFrame?.owner()
178184

179-
@Synchronized
180185
internal fun <T> probeCoroutineCreated(completion: Continuation<T>): Continuation<T> {
181186
if (!isInstalled) {
182187
return completion
@@ -197,22 +202,24 @@ internal object DebugProbesImpl {
197202
* even more verbose (it will attach coroutine creation stacktrace to all exceptions),
198203
* and then using this artificial frame as an identifier of coroutineSuspended/resumed calls.
199204
*/
200-
val stacktrace = sanitizedStackTrace(Exception())
201-
val frames = ArrayList<CoroutineStackFrame?>(stacktrace.size)
202-
for ((index, frame) in stacktrace.reversed().withIndex()) {
203-
frames += object : CoroutineStackFrame {
204-
override val callerFrame: CoroutineStackFrame?
205-
get() = if (index == 0) null else frames[index - 1]
206-
205+
val stacktrace = sanitizeStackTrace(Exception())
206+
val frame = stacktrace.foldRight<StackTraceElement, CoroutineStackFrame?>(null) { frame, acc ->
207+
object : CoroutineStackFrame {
208+
override val callerFrame: CoroutineStackFrame? = acc
207209
override fun getStackTraceElement(): StackTraceElement = frame
208210
}
209-
}
211+
}!!
210212

211-
val result = ArtificialStackFrame(completion, frames.last()!!)
212-
capturedCoroutines[result] = CoroutineState(completion, stacktrace.slice(1 until stacktrace.size), ++sequenceNumber)
213+
val result = ArtificialStackFrame(completion, frame)
214+
storeFrame(result, completion)
213215
return result
214216
}
215217

218+
@Synchronized
219+
private fun <T> storeFrame(frame: ArtificialStackFrame<T>, completion: Continuation<T>) {
220+
capturedCoroutines[frame] = CoroutineState(completion, frame, ++sequenceNumber)
221+
}
222+
216223
@Synchronized
217224
private fun probeCoroutineCompleted(coroutine: ArtificialStackFrame<*>) {
218225
capturedCoroutines.remove(coroutine)
@@ -230,7 +237,7 @@ internal object DebugProbesImpl {
230237
override fun toString(): String = delegate.toString()
231238
}
232239

233-
private fun <T : Throwable> sanitizedStackTrace(throwable: T): Array<StackTraceElement> {
240+
private fun <T : Throwable> sanitizeStackTrace(throwable: T): List<StackTraceElement> {
234241
val stackTrace = throwable.stackTrace
235242
val size = stackTrace.size
236243

@@ -243,7 +250,7 @@ internal object DebugProbesImpl {
243250
}
244251

245252
if (!DebugProbes.sanitizeStackTraces) {
246-
return Array(size - probeIndex) {
253+
return List(size - probeIndex) {
247254
if (it == 0) artificialFrame(ARTIFICIAL_FRAME_MESSAGE) else stackTrace[it + probeIndex]
248255
}
249256
}
@@ -255,7 +262,6 @@ internal object DebugProbesImpl {
255262
*/
256263
val result = ArrayList<StackTraceElement>(size - probeIndex + 1)
257264
result += artificialFrame(ARTIFICIAL_FRAME_MESSAGE)
258-
Thread.sleep(1)
259265
var includeInternalFrame = true
260266
for (i in (probeIndex + 1) until size - 1) {
261267
val element = stackTrace[i]
@@ -278,7 +284,7 @@ internal object DebugProbesImpl {
278284
}
279285

280286
result += stackTrace[size - 1]
281-
return result.toTypedArray()
287+
return result
282288
}
283289

284290
private val StackTraceElement.isInternalMethod: Boolean get() = className.startsWith("kotlinx.coroutines")

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

Lines changed: 31 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -51,8 +51,7 @@ class CoroutinesDumpTest : TestBase() {
5151

5252
val found = DebugProbes.dumpCoroutinesState().single { it.jobOrNull === deferred }
5353
assertSame(deferred, found.job)
54-
deferred.cancel()
55-
runBlocking { deferred.join() }
54+
runBlocking { deferred.cancelAndJoin() }
5655
}
5756

5857
@Test
@@ -75,8 +74,7 @@ class CoroutinesDumpTest : TestBase() {
7574
"\tat kotlinx.coroutines.BuildersKt__Builders_commonKt.async\$default(Builders.common.kt)\n" +
7675
"\tat kotlinx.coroutines.BuildersKt.async\$default(Unknown Source)\n" +
7776
"\tat kotlinx.coroutines.debug.CoroutinesDumpTest.testRunningCoroutine(CoroutinesDumpTest.kt:49)")
78-
deferred.cancel()
79-
runBlocking { deferred.join() }
77+
runBlocking { deferred.cancelAndJoin() }
8078
}
8179

8280
@Test
@@ -102,8 +100,34 @@ class CoroutinesDumpTest : TestBase() {
102100
"\tat kotlinx.coroutines.BuildersKt.async\$default(Unknown Source)\n" +
103101
"\tat kotlinx.coroutines.debug.CoroutinesDumpTest.testRunningCoroutineWithSuspensionPoint(CoroutinesDumpTest.kt:71)"
104102
)
105-
deferred.cancel()
106-
runBlocking { deferred.join() }
103+
runBlocking { deferred.cancelAndJoin() }
104+
}
105+
106+
@Test
107+
fun testCreationStackTrace() = synchronized(monitor) {
108+
val deferred = GlobalScope.async {
109+
activeMethod(shouldSuspend = true)
110+
}
111+
112+
awaitCoroutineStarted()
113+
val coroutine = DebugProbes.dumpCoroutinesState().first()
114+
val result = coroutine.creationStackTrace.fold(StringBuilder()) { acc, element ->
115+
acc.append(element.toString())
116+
acc.append('\n')
117+
}.toString().trimStackTrace()
118+
119+
runBlocking { deferred.cancelAndJoin() }
120+
121+
val expected = ("kotlin.coroutines.intrinsics.IntrinsicsKt__IntrinsicsJvmKt.createCoroutineUnintercepted(IntrinsicsJvm.kt:116)\n" +
122+
"kotlinx.coroutines.intrinsics.CancellableKt.startCoroutineCancellable(Cancellable.kt:23)\n" +
123+
"kotlinx.coroutines.CoroutineStart.invoke(CoroutineStart.kt:109)\n" +
124+
"kotlinx.coroutines.AbstractCoroutine.start(AbstractCoroutine.kt:160)\n" +
125+
"kotlinx.coroutines.BuildersKt__Builders_commonKt.async(Builders.common.kt:88)\n" +
126+
"kotlinx.coroutines.BuildersKt.async(Unknown Source)\n" +
127+
"kotlinx.coroutines.BuildersKt__Builders_commonKt.async\$default(Builders.common.kt:81)\n" +
128+
"kotlinx.coroutines.BuildersKt.async\$default(Unknown Source)\n" +
129+
"kotlinx.coroutines.debug.CoroutinesDumpTest.testCreationStackTrace(CoroutinesDumpTest.kt:109)").trimStackTrace()
130+
assertTrue(result.startsWith(expected))
107131
}
108132

109133
@Test
@@ -113,8 +137,7 @@ class CoroutinesDumpTest : TestBase() {
113137
}
114138

115139
awaitCoroutineStarted()
116-
deferred.cancel()
117-
runBlocking { deferred.join() }
140+
runBlocking { deferred.cancelAndJoin() }
118141
verifyDump()
119142
}
120143

0 commit comments

Comments
 (0)