RUM timestamp is inconsistent with other agent timestamps

[pgross41]

I saw APM Server is slapping its own timestamp on client data #723. This adds a timestamp for when the transaction ends (plus some network lag). However, the timestamp coming from the Java agent is when the transaction begins.

Since APM Server knows the duration of the transaction, does it make sense to subtract the duration from "now" so that the timestamps always represent begin time?

[simitt]

Thanks for the suggestion @pgross41 , I think that is an interesting proposal.

Since we do require a duration on transactions we could definitly calculate this for transactions. This could also be applied for the cases where a start is sent for spansand we add it to the transaction or request timestamp.

For error events we don't have any hint about a duration (which makes sense).

[simitt]

@elastic/apm-ui would this change break anything on the current UI implementation?

[sorenlouv]

would this change break anything on the current UI implementation?
@simitt

No, this would not break the UI. On the contrary it will probably improve the accuracy of the timeline.
+1 for this change.

[simitt]

@roncohen are you ok with moving forward with this and changing the timestamp to the beginning of an event where possible (transaction, span)?

[roncohen]

@simitt to be clear, you'd set this?:

transactions:
timestamp.us = request time - transaction.duration

spans:
timestamp.us = request time - span.start

@sqren you should be aware that for the distributed timeline, timings for RUM data and backend data will still not be aligned. Amongst other things, the RUM agent waits a bit before sending up data which means request time isn't exactly when the RUM transaction finished.

[roncohen]

@pgross41 do you have a specific use case in mind? the APM UI currently adjusts spans so things look right on the distributed timeline.

[pgross41]

@roncohen We just recently implemented distributed tracing so I have not had a chance to explore that data yet. This initially came up because I was investigating the root cause of a request that timed out. The inconsistency of the "timestamp" field makes it difficult to determine what time exactly the timeout actually occurred. I understand the RUM agent could be a few seconds delayed but that is expected.

[sorenlouv]

you should be aware that for the distributed timeline, timings for RUM data and backend data will still not be aligned. Amongst other things, the RUM agent waits a bit before sending up data which means request time isn't exactly when the RUM transaction finished.

@roncohen This is fine. My intention is not to remove the logic we have for re-ordering - but I'm hoping it'll kick in less often with this change. That way the transaction/spans timestamps will (hopefully) make more sense when comparing them to the visual timeline.

[roncohen]

gotcha. I'm fine to move forward on the suggested option 👍

[axw]

transactions:
timestamp.us = request time - transaction.duration

spans:
timestamp.us = request time - span.start

I started looking into this, and I don't think this span calculation is quite right? span.start is an offset from the transaction start time, so I would expect timestamp.us = request time - transaction.duration + span.start

We can address this for the RUM v3 protocol, which encodes spans within their enclosing transaction.

In the v2 protocol spans aren't aware of their enclosing transaction in the v2 protocol. I think the RUM agent always sends spans and transactions in the same payload, but making the server aware of that is going be invasive. I'm going to defer that for now.

[axw]

In the v3 protocol errors are not embedded in transactions, so we can't adjust their timestamps in the same way. Errors will be misplaced on the timeline then. So we might have to make a more invasive change for this after all.