elastic / elastic/apm-agent-nodejs
two apm.startTransaction() in the same millisecond can have out of order `timestamp`
- Dominant language
- JavaScript
- Stars
- 594
- Forks
- 244
- Avg merge
- 1d 8h
- Merged PRs (30d)
- 16
Description
With code like this:
```js
// ...
var t1 = apm.startTransaction('t1')
var t2 = apm.startTransaction('t2')
var t3 = apm.startTransaction('t3')
// ...
```
One sometimes (often) gets trace data where `t3.timestamp` is *before* `t2.timestamp`, e.g.:
```
{
"transaction": {
"name": "t3",
"timestamp": 1628203089499003,
...
{
"transaction": {
"name": "t2",
"timestamp": 1628203089499004,
```
This is handled by "lib/instrumentation/timer.js" and this code from relative-microtime package:
https://github.com/watson/relative-microtime/blob/e91dbc903809d5b5e1228e6a28b84f0032871b9a/index.js#L3-L13
Here is a run with some debug prints to try to show what is happening:
```
XXX startTransaction: start, name=t1
XXX hrtime diff [ 0, 63817 ]
XXX create new Timer: parent=undefined startTime=undefined start=1628204997326063
XXX startTransaction: start, name=t2
XXX hrtime diff [ 0, 4093 ]
XXX create new Timer: parent=undefined startTime=undefined start=1628204997328004
XXX startTransaction: start, name=t3
XXX hrtime diff [ 0, 3509 ]
XXX create new Timer: parent=undefined startTime=undefined start=1628204997328003
```
- t2 and t3 are getting the same `microStart = Date.now() * 1000` when they start in the same millisecond
- Each transaction gets an independent `return function microtime () { ... }` timer to be able to calculate time relative to the start of that transaction.
- The `timestamp` for the transaction is from calling that returned `function microtime () { ... }`, which adds the difference between two calls to `process.hrtime()`, one in each of these lines: https://github.com/elastic/apm-agent-nodejs/blob/73e7d605830fd9d7579ef1593e7e8d85b5799259/lib/instrumentation/timer.js#L14-L15
- On my dev machine that hrtime diff is fairly consistently 4us for t2 and 3us for t3.
I think the issue is minor. Transactions are independent, and having two or more of them started *synchronously* in the same async task is a contrived example.
One option for "fixing" this, I think, would be to elide the microseconds-resolution for the "start" time of the transaction. In other words, the start time of the timer (and the transaction using it) is the `Date.now()`, which doesn't have microsecond resolution.
Another option might be to have a module-level `process.hrtime()` base used as a common comparison base time to include in the relative calculations.
Contributor guide
Assessment
This issue has not been assessed yet.