Provide a supported way to get anchored clock times #3279
Comments
|
Just to have more context/understanding on the background issue you are addressing, is it related that the wall clock would be non monotonic (for instance a NTP update, could adjust the clock negatively) and you could end up with negative spans ? |
There are a couple issues at play here. Originally we used the monotonic clock in order to ensure spans always end after they start even if the system clock is modified during an operation. This can cause issues because the monotonic clock can be paused for various reasons including computer sleeping, lambda runtime pausing, and possibly others. This caused the clock to shift farther and farther into the past as the process lived longer. The monotonic clock also drifts naturally from the system clock as it is not NTP sync'd. The solution we came up with was to use the system clock to determing the "real" time at the start of a trace, and use the monotonic clock for the rest of the trace. This ensures the whole trace is never drifted too far from real time, but also that times are monotonic within a trace. |
|
Ok the solution makes a lot of sense, especially if you consider the spans to be short-lived (few seconds) compared to the process. So I guess it would not be appropriate for the API to expose a single current time, as you have a current time per trace (absolute start time of trace + delta in monotonic time), it would be natural to scope it by trace in the API. |
|
Also as a basic / first-time user of Otel I don't see any particular use case where I would want to mess with the underlying clock. Do you have any specific use cases in mind, or is it to let flexibility on the user API (or just to be able to switch the strategy easily at a later point internally) ? The sole use case (I can think of) where I would set manually the start/end time of spans is if I am getting logs / events in a legacy db and I want to convert them to traces afterward, but the current trace time would not help here. |
Agree that is not possible as the anchor is on the span currently and propagated to children. So one anchor per trace part within a process, We could move away from using one anchor per process local trace by using the global anchored clock always. if anchor moves between span start/end SDK should ensure that end >= start. If timestamps are used also in logs, metrics it's currently a bit confusing to have spans adjusted but the other parts not. |
It's not that unusual to have spans with duration of hours. e.g. some CI run consisting of several builds and tests. |
In that case why not just use |
|
As far as I remember high precision timing (better then ms) was one initial targets. Should we should add some hint in the API docs that specifying start/end/... times is likely a bad idea? Should we also change span.end() to ensure that end>=start instead of only logging but keeping the invalid value? |
That's what I remember too. Wouldn't be too hard to change all the existing clock methods to use Date behind the scenes. Possible to get bad span times during NTP syncs and other things like that but it shouldn't be that many bad spans/traces. We already have the problem where different hosts might have different times.
I think we should at least do this. There is no case where an end<start is a good thing.
We should at least document the possible problems if inconsistent times are somehow used. |
|
Just a suggestion/thinking out loud (and probably not applicable due to the existing API ^^), but why not having a "hot" span API intended for live tracing where you cannot specify the times, and a "cold" span API where you are responsible to set both start and end dates. |
Mostly because that is not what was in the API specification |
|
@gregolsen provided an alternative suggested solution in #3320 where he makes the anchored clock available in the API |
Created a PR for this #3327 |
|
Copying some conversation with @gregolsen in #3320 as it is relevant here:
From the above conversation, I actually think it is worth considering an |
|
Just a bit of interesting context on system clock drift. I also ran an experiment in production – I added start/end timestamps based on system clocks to all the spans. P999 (99.9 percentile) is 3.9 milliseconds however there are lots of outliers – 2 on logarithmic scale means 100 milliseconds difference between the original duration and the one computed based on the system clock. Filtering out to only the spans with over 10ms difference in measured durations we can see that the relative mismatch is not as bad: with AVG duration of 900ms the AVG difference is 28ms ~3.1%.
I also found an interesting span (link is private, just storing for myself) which duration was recorded as 900ms (we are using OTE 1.6.0 at the moment) but, based on system clock, its duration is 0. I would trust system clock here as those cache lookups like are typically under a millisecond in duration. So, somehow, monotonic clock measured 900ms out of nowhere:
|
|
This trace from the comment above is actually really interesting – looks like there was a system clock adjustment by 915ms – it happened between the long span of 914.7ms and the previous span. But the fact that the long span is exactly 914.7ms means that the performance API monotonic duration also jumped by 915ms (hence the span duration). How is that possible that both the system clock and values returned by We also have
|
|
Thanks for doing the research. Great to have hard numbers. Contingent on my correct understanding of the graph, here are the conclusions I think we can draw:
My understanding of NTP under normal operation is that unless a manual adjustment is made like you did there, it doesn't make large jumps, but instead modifies the system clock to run slower or faster as needed. Obviously in a browser environment you have no idea what the user will do with their system clock. I ran the script in safari for admittedly much less time but it seems to stay within about 1ms. I'll let it keep running for a while and do an ntp update in about 30 minutes to see if that changes things.
I know browser vendors play with clocks in order to prevent fingerprinting, so I'm not sure what effect that may have on either or both clocks. I also wouldn't put it past browsers to implement these sorts of things themselves instead of relying on the actual system clock, so this behavior could easily vary from browser to browser.
I was also under the impression that it was not subject to adjustments. This is interesting information. are you sure that span didn't actually take 914ms? That's quite a large jump. It also looks like the next few spans took less time than the spans leading up to it. Not sure what happened there. |
|
I, of course, can't be 100% sure but those spans are cache lookups where the cache is simply an in-memory lru-cache – they are extremely fast and 914ms seems unlikely. But also what are the odds of a system clock jumping for the exact same amount before the span has ended? If the |
|
After running quite a bit longer safari seems... consistent
|
|
Oh, sorry - I forgot to mention, I'm not sure if safari is a good candidate for investigations as it doesn't seem like suffering from a difference between system clock and |
|
We are measuring clock drift on every span by running |
Yeah I'm really not sure what to make of that. I'm not very familiar with the particular performance characteristics of that module and even if I was I don't know much about your use of it. What units are you measuring drift in? 24 million anythings for chrome seems like quite a gap from the system clock. Your graphs definitely seem to show chrome as the "problem child" |
|
Also, it's not really clear which if either of the clocks is more correct. We only know the difference between them |
|
I just found a counter example to my idea that Chrome is indeed a problem child - those units are milliseconds, so 2,709,469,466 milliseconds is 2,709,469,466 / 1000 / 3600 / 24 = 31 day of a difference between We have instrumented spans with many timestamps: we have the original timestamp set by OTEL (comes from hrTime()), proxy timestamp (we proxy all spans via our backend API) and also Honeycomb provides ingestion timestamp when it got the span into their system. Proxy timestamp, system clock and ingestion time are in alignment, while the timestamp set by OTEL is far in the past thanks to the computers sleeping. Here are two heatmaps - for positive clock drift and negative. Negative clock drift is tiny while positive drift has gigantic outliers.
|
This is unfortunately not that uncommon from my (admittedly recently acquired) understanding. I think chrome's timeorigin might be calculated from the browser startup not from each tab start?
Interesting. Even with the new anchored clock implementation you have drifts this bad? Or is this just direct hrTime measuring not the span time? |
|
Created #3359 as a proposal to show how we can remove the anchored clock from the tracer while we work on a more full solution. I really don't want to remove the anchored clock as we will just reintroduce those old problems, but the new problems seem worse IMO /cc @Flarna we had discussions which led to the original anchored clock. if you see a better way to resolve these issues without reverting I would appreciate it |
|
Unfortunately I have no idea how to fix this easy. I was about proposing to revert but seems you were faster. API allows to pass start/end time independent of each other using any timestamp source user wants. And actually this happens in the wild. I think this is a major design flow in API. To my understanding there are use cases (at least in browser) where performance must be used - but we know it's drifting. Maybe there is a solution for non browser environments by creating an API to get the current time from the one and only (configurable) time source and dissallow the use of any other time sources. But no idea how to disallow this (besides via doc). |
|
For browsers considering that
The easiest fix for data coming from performance API would be to add the drift to timeorigin that is used to convert relative performance timestamp to absolute timestamp return timeOrigin + (Date.now() - (timeOrigin + performance.now()));
// which can be math'd into
return timeOrigin + Date.now() - timeOrigin - performance.now();
// which simplifies to
return Date.now() - performance.now();This way also if user records timestamps manually somewhere
|
|
I'm not a browers expert so asking here. which category of the above 3 is used by instrumentation-fetch here? |
|
|
|
@t2t2 please correct me if I'm wrong but if the Some data to back this hypothesis up (unfortunately you won't be able to access the links provided, I'm adding them for myself to have original queries/traces in case more info needed): Here's a sample trace. Here you can see how
|
To summarize the facts of these two APIs as I understand them:
While I generally like @gregolsen's ideas around keeping fields for all
|
|
John's suggestion is one that has been brought up in the past. The biggest downside is that it is susceptible to ntp changes mid trace |
Yep. For the purposes of lining up with other data streams (e.g.,log timestamps) we need at least one timestamp as close to reality as we can get. Whether NTP resets backwards or forwards it'll make everything (not just traces) a bit weird to interpret. We could have |
So this would likely not be an issue for resource timings as they all would be translated in one batch at the end of span (and tbh for fetch and xhr it'd be more accurate to have both span start and end time from resource timings), however there probably could be nanosecond level rounding errors between calls (since performance.now and Date.now have different precisions rounding could give different values, which could be solved by memoizing the value as long as it hasn't changed more than eg. ms) and accepting that the data accuracy is going to be around ms (which considering anything actionable - be it long blocking tasks or slow http calls - would have duration in 10 - 1000ms anyway, it'd be good enough considering the situation) For custom spans it's definitely more suspectible to mid-span NTP updates, but here I think just the reality of the amount of garbage data now from performance API time drift is >>>> the amount of data garbaged by NTP, that personally it would go "yeah 0.0...01% of RUM data is just gonna end up being gabrage, but at least it has many zeroes" eg one weekend later:
Code used to calculate abovefunction getCurrentTimestamps() {
const dnow = Date.now()
const pnow = performance.now()
return [dnow, performance.timeOrigin + pnow, new Date(dnow), new Date(performance.timeOrigin + pnow)]
}
const url = 'https://httpbin.org/response-headers?timing-allow-origin=*'
const obs = new PerformanceObserver((list) => {
list.getEntries().forEach(entry => {
if (entry.name !== url) {
return false
}
const table = {}
Object.keys(entry.toJSON()).forEach(key => {
table[key] = {}
if (typeof entry[key] !== 'number' || ['duration', 'transferSize', 'encodedBodySize', 'decodedBodySize'].includes(key)) {
table[key].value = entry[key]
} else {
table[key].value = entry[key]
table[key].withOrigin = performance.timeOrigin + entry[key]
table[key].withDrift = (Date.now() - performance.now()) + entry[key]
table[key].withOriginHuman = new Date(performance.timeOrigin + entry[key])
table[key].withDriftHuman = new Date((Date.now() - performance.now()) + entry[key])
}
})
console.table(table)
})
})
obs.observe({ entryTypes: ['resource'] })
console.log('drift check', ...getCurrentTimestamps())
fetch(url, {headers: {'x-custom': 'create-OPTIONS-req'}}).then(() => {
console.log('res time', ...getCurrentTimestamps())
}) |
I think this is not a problem since the timing API is intentionally jittered anyway in order to prevent timing attacks |
|
Codeconst start = performance.now()
const microtasker = Promise.resolve()
function getDiff() {
microtasker.then(() => {
console.log('diff', Date.now() - performance.now())
if (performance.now() - start <= 1) {
getDiff()
}
})
}
getDiff()I can see there being an issue with one call saying add 49.4 and next 50.3 |
|
Proposed timestamp resolution flow for span durations: // onStart and onEnd provided only for purposes of defining the terms used in the flow chart
// they do not indicate new methods or callbacks on the span
onStart() {
perf_start = performance.now()
perf_offset = Date.now() - this.perf_start
}
onEnd() {
perf_duration = performance.now() - perf_start
}flowchart TD
id1(start_time provided by user?)
id2(end_time provided by user?)
id3(duration = provided_end_time - provided_start_time)
id4(duration = Date.now - provided_start_time \n see note 1 below)
id5(start_time = Date.now)
id6(end_time provided by user?)
id7(duration = perf_duration\nsee note 2 below)
id8(provided_end_time - start_time > 0)
id9(end_time = provided_end_time)
id10(end_time = provided_end_time + perf_offset\nsee note 3 below)
id11(start_time = provided_start_time)
id1-- yes -->id11
id11 --> id2
id2-- yes -->id3
id2-- no --> id4
id1 -- no --> id5
id5 --> id6
id6 -- no --> id7
id6 -- yes --> id8
id8 -- yes --> id9
id8 -- no --> id10
Note 1: Since the user has provided a the start time but not the end time, we assume the operation was started somewhere out of process and we are just ending it. Note 2: Neither start time or end time is provided. The duration uses the monotonic clock to guard against NTP shifts, but the start time is calculated from Date.now to guard against performance clock drift Note 3: this time most likely comes from the browser performance timing API which has been shifted. |
|
I mostly agree with @dyladan's proposal diagram above, with a few exceptions, both on the "we provide start time, user provides end time" path:
|
What do you mean by "our" instrumentation? The OTel contrib instrumentation does this for xhr, fetch, and user interactoin plugins
Sorry if it wasn't clear but that's what the perf offset is. In that case, the start time comes from Date and the end time is shifted to be consistent with it
This would only happen if you provided an end time which is earlier than the start time, which is very unlikely if you use any clock other than the performance clock. If you are describing some outside operation where you read timestamps from logs you would most likely provide a start AND end timestamp and not trigger this path.
Seems reasonable. Exactly 0 seems almost impossible though if the start time is automatically generated and the end time is provided by the user. |
|
@johnbley did that satisfy your concerns? |
|
I think it's better than we had before, though I would still prefer simpler. For automatic timing I think it looks good. |
|
What about this? It's quite a bit simpler IMO. Basically we assume any timestamp const origin = getTimeOrigin();
start(time_input: TimeInput) {
const now = Date.now();
this.perf_start = performance.now()
this.perf_offset = now - this.perf_start
this.start_time_input = time_input;
if (typeof time_input === 'number' && time_input < performance.now()) {
// must be a performance entry. apply correction
this.start_time = msToHrTime(time_input + origin + this.perf_offset);
} else if (time_input != null) {
// do not apply correction in any other cases
this.start_time = convertToHrTime(time_input);
} else {
this.start_time = convertToHrTime(Date.now());
}
}
end(time_input: TimeInput) {
if (time_input != null) {
if (typeof time_input === 'number' && time_input < performance.now()) {
// must be a performance entry. apply correction
this.end_time = msToHrTime(time_input + origin + this.perf_offset);
} else {
// do not apply correction in any other cases
this.end_time = convertToHrTime(time_input);
}
this.duration = hrTimeDuration(this.start_time, this.end_time);
} else {
if (this.start_time_input != null) {
// user provided a start time input but not an end time input
// best we can do is use system time because we don't know if the span started when it was constructed or before
this.end_time = msToHrTime(Date.now());
this.duration = hrTimeDuration(this.start_time, this.end_time);
} else {
// user did not provide start or end time
// calculate end time from start time using performance timer
this.duration = hrTimeDuration(performance.now() - this.perf_start);
this.end_time = addHrTimes(this.start_time, this.duration)
}
}
// it is possible to have a negative duration if:
// user provides start time in the future and does not provide an end time
// user does not provide start time and provides an end time in the past (but not small enough to be considered a performance entry)
// user provides both start and end time and they are inconsistent
if (hrTimeIsNegative(this.duration)) {
this.duration = [0,0];
this.end_time = this.start_time;
}
}CC @t2t2 @legendecas @Flarna this is slightly different from the PR I opened PTAL and let me know which you think is better IMPORTANT: breaking change?Should this be considered a breaking change? The current behavior if the user provides a timestamp before the process start ( My perspective is that this should be considered non-breaking |
|
This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days. |
|
The anchored clock is not used in the span anymore. Superseded by #3434. |
Ref open-telemetry/opentelemetry-js-contrib#1193
Ref open-telemetry/opentelemetry-js-contrib#1209
I wanted to make an issue where we can discuss this separately from the contrib bugs and solve it in a more general way. Here is the relevant conversation so far:
The text was updated successfully, but these errors were encountered: