From 4f8fe7ddef0bd957147f25288a2fc0d543819509 Mon Sep 17 00:00:00 2001 From: Santiago Mattiauda Date: Mon, 2 Nov 2026 20:36:55 -0300 Subject: [PATCH 1/2] fix(runtime): keep span async slice begin/end ordered under concurrency The span transition and the matching beginAsyncSection/endAsyncSection call were two steps, so a concurrent Started could overtake a Finished and emit begin, begin, end on the same cookie. Perfetto then showed only the first part of the span. Run both inside one atomic per-key operation and add a multi-threaded regression test. --- CHANGELOG.md | 4 +++ .../structured/runtime/SystemTraceSink.kt | 18 +++++++--- .../structured/runtime/SystemTraceSinkTest.kt | 35 +++++++++++++++++++ 3 files changed, 52 insertions(+), 5 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0c770a0..b2e6009 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,10 @@ The format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/) and ## [Unreleased] +### Fixed + +- **`AndroidTraceSink` span slices truncated under concurrency**: the async slice `span:` could receive `begin`/`end` out of order when segments of one span started and finished on several threads, which made Perfetto show only the first fraction of the span (observed on an Android 15 emulator: ~110 ms of a 1.3 s span). The span transition and its trace call are now one atomic operation, so `begin`/`end` strictly alternate. Covered by a multi-threaded regression test. + ### Changed - Runtime family version bumped to `0.1.0-ALPHA02` (`RUNTIME_VERSION`); install snippets in the runtime READMEs now use it. diff --git a/coroutines-runtime/runtime/src/jvmAndAndroidMain/kotlin/io/github/santimattius/structured/runtime/SystemTraceSink.kt b/coroutines-runtime/runtime/src/jvmAndAndroidMain/kotlin/io/github/santimattius/structured/runtime/SystemTraceSink.kt index 9653c19..9ce9f8a 100644 --- a/coroutines-runtime/runtime/src/jvmAndAndroidMain/kotlin/io/github/santimattius/structured/runtime/SystemTraceSink.kt +++ b/coroutines-runtime/runtime/src/jvmAndAndroidMain/kotlin/io/github/santimattius/structured/runtime/SystemTraceSink.kt @@ -153,22 +153,30 @@ internal class SystemTraceSink( } } + // The map transition and the matching trace call run inside one atomic per-key operation, so + // begin/end reach the tracer in the same order as the 0 -> 1 and 1 -> 0 transitions. Doing the + // call after the map update let a concurrent Started overtake a Finished and interleave + // begin, begin, end on the same cookie. private fun spanStarted(spanId: Long, spanName: String?) { - val count = activeSpans.merge(spanId, 1) { a, b -> a + b } - if (count == 1) api.beginAsyncSection(spanSliceName(spanName), spanId.toInt()) + activeSpans.compute(spanId) { _, count -> + if (count == null) { + runCatching { api.beginAsyncSection(spanSliceName(spanName), spanId.toInt()) } + 1 + } else { + count + 1 + } + } } private fun spanFinished(spanId: Long, spanName: String?) { - var closed = false activeSpans.computeIfPresent(spanId) { _, count -> if (count <= 1) { - closed = true + runCatching { api.endAsyncSection(spanSliceName(spanName), spanId.toInt()) } null } else { count - 1 } } - if (closed) api.endAsyncSection(spanSliceName(spanName), spanId.toInt()) } private fun countersFor(label: String): Counters { diff --git a/coroutines-runtime/runtime/src/jvmTest/kotlin/io/github/santimattius/structured/runtime/SystemTraceSinkTest.kt b/coroutines-runtime/runtime/src/jvmTest/kotlin/io/github/santimattius/structured/runtime/SystemTraceSinkTest.kt index 5fff432..539dc49 100644 --- a/coroutines-runtime/runtime/src/jvmTest/kotlin/io/github/santimattius/structured/runtime/SystemTraceSinkTest.kt +++ b/coroutines-runtime/runtime/src/jvmTest/kotlin/io/github/santimattius/structured/runtime/SystemTraceSinkTest.kt @@ -370,4 +370,39 @@ class SystemTraceSinkTest { api.counters().filter { it.contains("queue_delay_max_us") }, ) } + + @Test + fun concurrentSegmentsOfOneSpanAlternateBeginAndEndStrictly() { + val async = java.util.Collections.synchronizedList(ArrayList()) + val api = object : SystemTraceApi { + override fun isEnabled() = true + override fun beginSection(name: String) = Unit + override fun endSection() = Unit + override fun setCounter(name: String, value: Long) = Unit + override fun beginAsyncSection(name: String, cookie: Int) { async += "begin" } + override fun endAsyncSection(name: String, cookie: Int) { async += "end" } + } + val sink = SystemTraceSink(api) + val threads = 8 + val perThread = 5_000 + val start = CountDownLatch(1) + val pool = Executors.newFixedThreadPool(threads) + repeat(threads) { + pool.execute { + start.await() + repeat(perThread) { + sink.emit(startedIn(5L, "storm")) + sink.emit(finishedIn(5L, "storm")) + } + } + } + start.countDown() + pool.shutdown() + assertTrue(pool.awaitTermination(60, TimeUnit.SECONDS)) + val seq = async.toList() + // A span is either open or closed: begin/end must alternate, starting with begin. + val broken = seq.zipWithNext().count { (a, b) -> a == b } + assertEquals(0, broken, "begin/end did not alternate $broken times out of ${seq.size}") + assertEquals(seq.size % 2, 0) + } } From 5564bd6117391e49f9736ad4ae7ab47c22d3ed25 Mon Sep 17 00:00:00 2001 From: Santiago Mattiauda Date: Mon, 2 Nov 2026 20:38:32 -0300 Subject: [PATCH 2/2] chore: release 0.1.0-ALPHA03 Bump RUNTIME_VERSION to 0.1.0-ALPHA03 and update the install snippets in the runtime READMEs and the changelog. --- CHANGELOG.md | 4 ++++ coroutines-runtime/README.md | 8 ++++---- coroutines-runtime/runtime-test/README.md | 2 +- coroutines-runtime/runtime-tracing/README.md | 2 +- coroutines-runtime/runtime/README.md | 4 ++-- gradle.properties | 2 +- 6 files changed, 13 insertions(+), 9 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index b2e6009..47bae2e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,10 @@ The format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/) and ## [Unreleased] +### Changed + +- Runtime family version bumped to `0.1.0-ALPHA03` (`RUNTIME_VERSION`); install snippets in the runtime READMEs now use it. + ### Fixed - **`AndroidTraceSink` span slices truncated under concurrency**: the async slice `span:` could receive `begin`/`end` out of order when segments of one span started and finished on several threads, which made Perfetto show only the first fraction of the span (observed on an Android 15 emulator: ~110 ms of a 1.3 s span). The span transition and its trace call are now one atomic operation, so `begin`/`end` strictly alternate. Covered by a multi-threaded regression test. diff --git a/coroutines-runtime/README.md b/coroutines-runtime/README.md index 2f56b47..5070e9e 100644 --- a/coroutines-runtime/README.md +++ b/coroutines-runtime/README.md @@ -40,17 +40,17 @@ runtime-benchmark ─────┘ ## Installation Group `io.github.santimattius`; all published runtime artifacts share the `RUNTIME_VERSION` from -`gradle.properties` (currently `0.1.0-ALPHA02`). +`gradle.properties` (currently `0.1.0-ALPHA03`). ```kotlin // build.gradle.kts (Kotlin Multiplatform) kotlin { sourceSets { commonMain.dependencies { - implementation("io.github.santimattius:structured-coroutines-runtime:0.1.0-ALPHA02") + implementation("io.github.santimattius:structured-coroutines-runtime:0.1.0-ALPHA03") } commonTest.dependencies { - implementation("io.github.santimattius:structured-coroutines-runtime-test:0.1.0-ALPHA02") + implementation("io.github.santimattius:structured-coroutines-runtime-test:0.1.0-ALPHA03") } } } @@ -59,7 +59,7 @@ kotlin { ```kotlin // build.gradle.kts (JVM / desktop tracing) dependencies { - implementation("io.github.santimattius:structured-coroutines-runtime-tracing:0.1.0-ALPHA02") + implementation("io.github.santimattius:structured-coroutines-runtime-tracing:0.1.0-ALPHA03") } ``` diff --git a/coroutines-runtime/runtime-test/README.md b/coroutines-runtime/runtime-test/README.md index 16756dd..9cf348f 100644 --- a/coroutines-runtime/runtime-test/README.md +++ b/coroutines-runtime/runtime-test/README.md @@ -10,7 +10,7 @@ and `TraceSinkContract` (reusable checks every `TraceSink` should pass). It is a ```kotlin commonTest.dependencies { - implementation("io.github.santimattius:structured-coroutines-runtime-test:0.1.0-ALPHA02") + implementation("io.github.santimattius:structured-coroutines-runtime-test:0.1.0-ALPHA03") } ``` diff --git a/coroutines-runtime/runtime-tracing/README.md b/coroutines-runtime/runtime-tracing/README.md index 373e269..93fe815 100644 --- a/coroutines-runtime/runtime-tracing/README.md +++ b/coroutines-runtime/runtime-tracing/README.md @@ -12,7 +12,7 @@ and span flows, which `android.os.Trace` cannot express. It is a separate artifa ```kotlin dependencies { - implementation("io.github.santimattius:structured-coroutines-runtime-tracing:0.1.0-ALPHA02") + implementation("io.github.santimattius:structured-coroutines-runtime-tracing:0.1.0-ALPHA03") } ``` diff --git a/coroutines-runtime/runtime/README.md b/coroutines-runtime/runtime/README.md index 1bbda08..6bcace9 100644 --- a/coroutines-runtime/runtime/README.md +++ b/coroutines-runtime/runtime/README.md @@ -32,10 +32,10 @@ toolkit's `PROJECT_VERSION`. kotlin { sourceSets { commonMain.dependencies { - implementation("io.github.santimattius:structured-coroutines-runtime:0.1.0-ALPHA02") + implementation("io.github.santimattius:structured-coroutines-runtime:0.1.0-ALPHA03") } commonTest.dependencies { - implementation("io.github.santimattius:structured-coroutines-runtime-test:0.1.0-ALPHA02") + implementation("io.github.santimattius:structured-coroutines-runtime-test:0.1.0-ALPHA03") } } } diff --git a/gradle.properties b/gradle.properties index 25b9296..6ad06c5 100644 --- a/gradle.properties +++ b/gradle.properties @@ -9,7 +9,7 @@ kotlin.code.style=official PROJECT_GROUP=io.github.santimattius PROJECT_VERSION=1.2.1 # :runtime versions independently on its own 0.x train (see coroutines-runtime/runtime/build.gradle.kts) -RUNTIME_VERSION=0.1.0-ALPHA02 +RUNTIME_VERSION=0.1.0-ALPHA03 # Maven Central mavenCentralPublishing=true signAllPublications=true