If you start a span (B) in the same async operation as a preceding span (A), the current agent (v3.8.0) will make A and B siblings. I think B should be a child span of A.
If you'd like to test your own expectations, here is a sort of survey: https://gist.github.com/trentm/63e5dbdeded8b568e782d1f24eab9536
Works as expected: each span in separate async ops
The common case (at least I assume) in node.js is that code significant enough to be a traced span are in separate async ops on the node.js event loop. E.g.:
app.get('/my-endpoint', (req, res) => {
var A = apm.startSpan('this is span A')
setTimeout(function () {
var B = apm.startSpan('this is span B')
setTimeout(function () {
B.end()
A.end()
}, 10)
}, 10)
})
For this case, the APM agent generates a trace like this (where indentation denotes a parent/child relationship):
- transaction: GET /my-endpoint
- span: this is span A
- span: this is span B
This works as I'd expect.
The contested case: multiple spans started in the same async op
app.get('/my-endpoint', (req, res) => {
var A = apm.startSpan('this is span A')
var B = apm.startSpan('this is span B')
B.end()
A.end()
})
For this code, the current APM agent generates a trace like this:
- transaction: GET /my-endpoint
- span: this is span A
- span: this is span B
I think this is a bug, or at least should be considered. My expectation for the above code is a trace like this:
- transaction: GET /my-endpoint
- span: this is span A
- span: this is span B
The patch
If you want to try it out, here is a patch to lib/instrumentation/index.js that changes to my expected behaviour: https://gist.github.com/trentm/63e5dbdeded8b568e782d1f24eab9536#file-the-diff
I'll start a draft PR in a little bit with that.
Proposal
If you start a span (B) in the same async operation as a preceding span (A), the current agent (v3.8.0) will make A and B siblings. I think B should be a child span of A.
If you'd like to test your own expectations, here is a sort of survey: https://gist.github.com/trentm/63e5dbdeded8b568e782d1f24eab9536
Works as expected: each span in separate async ops
The common case (at least I assume) in node.js is that code significant enough to be a traced span are in separate async ops on the node.js event loop. E.g.:
For this case, the APM agent generates a trace like this (where indentation denotes a parent/child relationship):
This works as I'd expect.
The contested case: multiple spans started in the same async op
For this code, the current APM agent generates a trace like this:
I think this is a bug, or at least should be considered. My expectation for the above code is a trace like this:
The patch
If you want to try it out, here is a patch to lib/instrumentation/index.js that changes to my expected behaviour: https://gist.github.com/trentm/63e5dbdeded8b568e782d1f24eab9536#file-the-diff
I'll start a draft PR in a little bit with that.
Proposal