open-telemetry / open-telemetry/opentelemetry-java-instrumentation
[Kotlin] Incorrectly linked spans, incorrect durations when Coroutine Dispatchers are used
Nobody has claimed this yet.
- Dominant language
- Java
- Stars
- 2.6k
- Forks
- 1.2k
- Avg merge
- 2d 18h
- Merged PRs (30d)
- 228
Description
Describe the bug
When using the Java Agent & annotation driven auto-instrumentation with Kotlin - and the Coroutine Dispatcher is used (to dispatch some Coroutines outside of the main thread); we see broken traces consistently. Here's how the traces appear to be broken:
- Functions within a Dispatched block appear as their own traces - their spans untethered to their direct parent or calling method (but sometimes still tethered to the parent's parent).
- As a consequence of (1), you see two spans for the same method; when there was only one execution of it.
- Methods that use Dispatch blocks have durations that are inaccurately reported - they appear to finish much quicker than the method actually does.
Steps to reproduce
A minimal reproducible example below.
companion object {
private val log = logger {}
fun runit() {
runBlocking {
log.info { "Starting the example" }
breakingSpans()
}
}
@JvmStatic
fun main(args: Array<String>) {
runit()
}
@WithSpan
suspend fun breakingSpans() {
kotlin.runCatching {
blockingWork()
usingIOPool()
}
}
@WithSpan
suspend fun blockingWork() {
delay(2000L)
}
@WithSpan
suspend fun usingIOPool() {
return withContext(Dispatchers.IO) {
fetchUpstreamResource()
log.info { "Finished getting upstream resource" }
}
}
@WithSpan
suspend fun fetchUpstreamResource(){
delay(2000L)
}
}
What did you expect to see?
- I expect to see a single
breakingSpanstrace per run. - I expect to see
fetchUpstreamResource,usingIOPoolandblockingWorkin the same trace. - I expect the durations of these methods to represent the time it took for them to complete - which is at least 2 seconds.
What did you see instead?
- I see multiple (3) traces from
breakingSpans- One with
breakingSpans->blockingWork(surprisingly and not the focus of this post since this is not Dispatched work butblockingWork's duration is also inaccurate) - One with
breakingSpans->usingIOPool(but duration ofusingIOPoolis inaccurate) - One with just
fetchUpstreamResource(but duration offetchUpstreamResourceis inaccurate)
- One with
Some pictures below to see how this looks; but also see the the Logs all the way at the end.
What version are you using?
opentelemetry-javaagent - version: 1.15.0
Environment
Compiler: Azul (OpenJDK) 16.0.2
OS: MacOS Monterey
Additional context
The logs are quite interesting as well, and show the 3 traces being emitted:
io.plutocard.ServerApp [req.id=null] Starting blockingWork
[otel.javaagent 2022-08-23 11:19:16:580 -0400] [main] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'Companion.blockingWork' : a67c5bfad57eb68d79dd239ea51dc0ea f0c9ea759b7231d3 INTERNAL [tracer: io.opentelemetry.opentelemetry-annotations-1.0:1.15.0-alpha] AttributesMap{data={thread.name=main, thread.id=1}, capacity=128, totalAddedValues=2}
[otel.javaagent 2022-08-23 11:19:16:580 -0400] [main] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'Companion.breakingSpans' : a67c5bfad57eb68d79dd239ea51dc0ea 09e8b492d7e466b7 INTERNAL [tracer: io.opentelemetry.opentelemetry-annotations-1.0:1.15.0-alpha] AttributesMap{data={thread.name=main, thread.id=1}, capacity=128, totalAddedValues=2}
2022-08-23 11:19:18.586 [main] INFO
io.plutocard.ServerApp [req.id=null] Finished blockingWork
2022-08-23 11:19:18.588 [main] INFO
io.plutocard.ServerApp [req.id=null] Started usingIOPool
[otel.javaagent 2022-08-23 11:19:18:587 -0400] [main] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'Companion.blockingWork' : f9518af01d2d50cfa01f90844baca7f7 2ec970a1fc21956d INTERNAL [tracer: io.opentelemetry.opentelemetry-annotations-1.0:1.15.0-alpha] AttributesMap{data={thread.name=main, thread.id=1}, capacity=128, totalAddedValues=2}
[otel.javaagent 2022-08-23 11:19:18:603 -0400] [main] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'Companion.usingIOPool' : d404221fd5b24595bda24fde15f1b780 e3843e87db13b61b INTERNAL [tracer: io.opentelemetry.opentelemetry-annotations-1.0:1.15.0-alpha] AttributesMap{data={thread.name=main, thread.id=1}, capacity=128, totalAddedValues=2}
[otel.javaagent 2022-08-23 11:19:18:603 -0400] [main] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'Companion.breakingSpans' : d404221fd5b24595bda24fde15f1b780 f2e62b9951c48a0f INTERNAL [tracer: io.opentelemetry.opentelemetry-annotations-1.0:1.15.0-alpha] AttributesMap{data={thread.name=main, thread.id=1}, capacity=128, totalAddedValues=2}
[otel.javaagent 2022-08-23 11:19:18:605 -0400] [DefaultDispatcher-worker-1] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'Companion.fetchUpstreamResource' : ef65b66b1081ac297646d5e0cd129ad4 cb76a767dbc0ef94 INTERNAL [tracer: io.opentelemetry.opentelemetry-annotations-1.0:1.15.0-alpha] AttributesMap{data={thread.name=DefaultDispatcher-worker-1, thread.id=20}, capacity=128, totalAddedValues=2}
2022-08-23 11:19:18.604 [DefaultDispatcher-worker-1] INFO
io.plutocard.ServerApp [req.id=null] Started fetchUpstreamResource
2022-08-23 11:19:20.611 [DefaultDispatcher-worker-1] INFO
io.plutocard.ServerApp [req.id=null] Finished fetchUpstreamResource
[otel.javaagent 2022-08-23 11:19:20:611 -0400] [DefaultDispatcher-worker-1] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'Companion.fetchUpstreamResource' : 0461ccfc74e6ae8b7d7cf1522c4d5f2c 2e4d70998f21930a INTERNAL [tracer: io.opentelemetry.opentelemetry-annotations-1.0:1.15.0-alpha] AttributesMap{data={thread.name=DefaultDispatcher-worker-1, thread.id=20}, capacity=128, totalAddedValues=2}
[otel.javaagent 2022-08-23 11:19:20:611 -0400] [main] INFO io.opentelemetry.exporter.logging.LoggingSpanExporter - 'Companion.breakingSpans' : 96cd29c74e0d1e99db3ab94876aa8797 faedee63fcaa99da INTERNAL [tracer: io.opentelemetry.opentelemetry-annotations-1.0:1.15.0-alpha] AttributesMap{data={thread.name=main, thread.id=1}, capacity=128, totalAddedValues=2}
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Start with the minimal Kotlin example using the Java Agent, @WithSpan, runBlocking, and withContext(Dispatchers.IO), and reproduce the traces with the logging exporter. Trace context should remain linked across dispatched coroutines, each method should produce one span, and span durations should cover the actual delay and dispatched work.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- java, kotlin
- Domain
- observability
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 35/100