1413352 - validate timestamps used for activity-stream performance telemetry

Status: RESOLVED WONTFIX

(Firefox :: New Tab Page, enhancement, P2)

Description

[Dan Mosedale (:dmosedale, :dmose)]

Activity Stream is implemented partly in chrome (which mostly runs on the main thread of the main process), and partly in content (which mostly runs in the main thread of a content process).

We have PerfService code used both in chrome and content, it is effectively a wrapper around Window.performance objects.  In chrome, we use `Services.appShell.hiddenDOMWindow.performance` (which, as far as I know, runs on the main thread of the main process -- :mconley, is that true?).  In content, we just use the performance object of the content window/tab that we happen to be running in.

The timestamps we send to telemetry are all [converted to an "absolute" version of the timestamp by adding the PerformanceEntry.startTime of the thing marked with performance.mark() to performance.timeOrigin on the same object](https://github.com/mozilla/activity-stream/blob/master/system-addon/common/PerfService.jsm#L96).  

The idea is that since the timeOrigin is an actual time, and since all of these processes are on the same machine, we should be able to compare these "absolute timestamps" across arbitrary chrome and content processes.

Based on some discussions between :Mardak and :mconley, there's some question in our minds about whether this could be false in some cases.

Comment 1

[Dan Mosedale (:dmosedale, :dmose)]

:mconley, :baku, :valentin, is there any reason that these assumptions might not hold true? 

Separately from that, :baku and :valentin, I've noticed there have been some changes in the performance timing code recently.  I don't _think_ any of them would have changed the data we've generated using this algorithm.  Can you confirm or deny that?

Comment 2

[Dan Mosedale (:dmosedale, :dmose)]

To be clear, that second thing I'm hoping to get clarity about is whether the generated data would have been changed by any platform-level changes between 56, 57, and 58, since we are trying to look at data across those releases.

Comment 3

[Dan Mosedale (:dmosedale, :dmose)]

I could imagine that the mechanism for ensuring the guarantee that performance.now is monotonically increasing in a single browser context might introduce a bit of skew, but I'm guessing/hoping it's unlikely to be a meaningful amount in the majority of cases.  Given that almost all of the data that is batched together/compared is for a single about:newtab or about:home load, meaning that they should almost all be fairly localized in time, and thus the content numbers would be offset by a similar or identical amount from the chrome numbers.

Comment 4

[Mike Conley (:mconley) (:⚙️)]

(In reply to Dan Mosedale (:dmose) from comment #0)
> `Services.appShell.hiddenDOMWindow.performance` (which, as far as I know,
> runs on the main thread of the main process -- :mconley, is that true?).

Yes, I believe so.

> Based on some discussions between :Mardak and :mconley, there's some
> question in our minds about whether this could be false in some cases.

What are these questions, and what are the cases? When I dealt with this in bug 1372261, I was dealing with the test writer (who happened to be me a few years back!) passing Date.now() values around between processes to try to do meaningful timings for a performance benchmark. What I discovered is that, at least on Windows, Date.now() is not guaranteed to be monotonic - as in, two processes could ask the machine for Date.now() at exactly the same time (on two different cores) and get two different results.

I believe performance.now() is supposed to work around that kind of clock skew.

So can you give some detail on where things are breaking down for you?

Comment 5

[Valentin Gosu [:valentin]]

I remember we added a release assert at some point to make sure that the timestamps are monotonically increasing across processes, and had to back it out because it failed on somewhat old windows boxes.

There's some discussion in bug 1321878, and I filed bug 1336238 to find a way of determining if the timestamps are valid across processes, but it didn't get much attention.

I don't know exactly which windows architectures/versions are affected. Finding that out would probably be enough to filter the telemetry to only data you can trust.

Comment 6

[Valentin Gosu [:valentin]]

(In reply to Valentin Gosu [:valentin] from comment #5)
> I don't know exactly which windows architectures/versions are affected.
> Finding that out would probably be enough to filter the telemetry to only
> data you can trust.

Bug 1321878 comment 34 does list a few, but the list is definitely not complete.

Comment 7

[Dan Mosedale (:dmosedale, :dmose)]

First off, I'm going to make the problem more concrete so that it's easier to reason about.  Here it goes:

High-level question: can time durations for performance measurement be reliably computed from JavaScript across by comparing a window.performance timestamps collected in a JSM with ones collected in a content page in some arbitrary process using the performance.timeOrigin property to translate?

From the main thread in the main process, in a JSM:

    let hiddenWinPerf = Services.appShell.hiddenDOMWindow.performance;

    hiddenWinPerf.mark(“JSM-start-mark”);
    let jsmStartMark = hiddenWinPerf.getEntriesByType(“JSM-start-mark”)[0];
    let jsmStartTime = jsmStartMark.start + hiddenWinPerf.timeOrigin;

From a content window in some unknown content process:

    performance.mark(“content-end-mark”);
    let contentEndMark = performance.getEntries.ByType(“content-end-mark”)[0];
    let contentEndTime = contentEndMark.start + performance.timeOrigin;

And later, from wherever:

    let duration = contentEndTime - jsmStartTime;

Will duration be correct some/most/all of the time?

More details about specific concerns coming up...

Comment 8

[Dan Mosedale (:dmosedale, :dmose)]

So, thanks to Mike and Valentin, who have helped shed a bunch of light already.  I'll go try and track down more details about those Windows machines and what percentage they likely make up of our existing telemetry and how we might be able to exclude them.

(In reply to Mike Conley (:mconley) (:⚙) - Backlogged on reviews and needinfos from comment #4)
> > `Services.appShell.hiddenDOMWindow.performance` (which, as far as I know,
> > runs on the main thread of the main process -- :mconley, is that true?).

I just talked to Gijs, and he confirmed this.
 
> Yes, I believe so.
> 
> > Based on some discussions between :Mardak and :mconley, there's some
> > question in our minds about whether this could be false in some cases.
> 
> What are these questions, and what are the cases? When I dealt with this in

Another thing that could conceivably be a problem is, setting aside the cases which don't have the problem Valentin described (as I understand it from looking at those other bugs, Mac, Linux, and "newer" Windows boxes), whether the mechanism that keeps each performance context as monotonically increasing does so identically.

A couple of examples I could imagine, particularly if the mechanism for this is separate for each performance object, and particularly for machines which get frequent NTP clock adjustments because of a clock(s?) that are too slow or too fast or jittery:

* if the monotonically increasing mechanism is triggered only by calls to (eg) performance.mark/performance.now, there could conceivably be an imbalance of those across the different contexts.  Could this cause a meaningful problem?

* since the hidden DOM window is long-lived, it could accumulate perhaps a non-trivial number of changes on a machine that is regularly adjusted by NTP because its clock chip(s?) is too slow or too fast, whereas a new content window would have a timeOrigin that started much later and had many fewer adjustments.  Could this cause a problem?

Comment 9

[Jeff Muizelaar [:jrmuizel]]

(In reply to Dan Mosedale (:dmose) from comment #7)
> First off, I'm going to make the problem more concrete so that it's easier
> to reason about.  Here it goes:
> 
> High-level question: can time durations for performance measurement be
> reliably computed from JavaScript across by comparing a window.performance
> timestamps collected in a JSM with ones collected in a content page in some
> arbitrary process using the performance.timeOrigin property to translate?

No. timeOrigin is based on real time clock and so it can go backwards.

Further based on how mozilla::TimeStamp is implemented on Windows, we can't even guarantee that two processes with matching timeOrigins will have performance.now() timestamps that behave monotically compared to each other. (We could choose to fix this by eliminating the process local state that we have in the Windows implementation)

However, while we can't make certain guarantees things will most of the time be well behaved, and so in aggregate can probably be relied on.

Comment 10

[:Gijs (he/him)]

(In reply to Dan Mosedale (:dmose) from comment #0)
> The timestamps we send to telemetry are all [converted to an "absolute"
> version of the timestamp by adding the PerformanceEntry.startTime of the
> thing marked with performance.mark() to performance.timeOrigin on the same
> object](https://github.com/mozilla/activity-stream/blob/master/system-addon/
> common/PerfService.jsm#L96).  
> 
> The idea is that since the timeOrigin is an actual time, and since all of
> these processes are on the same machine, we should be able to compare these
> "absolute timestamps" across arbitrary chrome and content processes.

Based on comments so far, this seems like the root of many possible problems. Why are you trying to do this? That is, why do you need to compare absolute timestamps across processes? Not doing this would let you just use monotonically increasing perf.now() markers per-process, which are much better-understood and don't have any of the issues you're concerned about.

More generally, why this bug ("what are you actually trying to do?")? Do you think the data (what data?) you have is wrong because it looks wrong, or 'only' because you suspect there are theoretical/implementation issues with what you've done?
(this question partly because there's no significant context on the bug, and partly because of Jeff's comment #9's trailing comment:

(In reply to Jeff Muizelaar [:jrmuizel] from comment #9)
> However, while we can't make certain guarantees things will most of the time
> be well behaved, and so in aggregate can probably be relied on. )

Comment 11

[Dan Mosedale (:dmosedale, :dmose)]

(In reply to :Gijs (slow, PTO recovery mode) from comment #10)
> (In reply to Dan Mosedale (:dmose) from comment #0)
> > The timestamps we send to telemetry are all [converted to an "absolute"
> > version of the timestamp by adding the PerformanceEntry.startTime of the
> > thing marked with performance.mark() to performance.timeOrigin on the same
> > object](https://github.com/mozilla/activity-stream/blob/master/system-addon/
> > common/PerfService.jsm#L96).  
> > 
> > The idea is that since the timeOrigin is an actual time, and since all of
> > these processes are on the same machine, we should be able to compare these
> > "absolute timestamps" across arbitrary chrome and content processes.
> 
> Based on comments so far, this seems like the root of many possible
> problems. Why are you trying to do this? That is, why do you need to compare
> absolute timestamps across processes? Not doing this would let you just use
> monotonically increasing perf.now() markers per-process, which are much
> better-understood and don't have any of the issues you're concerned about.

That would indeed remove some uncertainty, which would be nice, but...

We're trying to gather perceived-performance telemetry around a variety of things, and we want to be able to see how things relate to each other (eg in what order various things happen).  Lots of them are about loading about:newtab or about:home, and those are typically based on user actions related to the main process (e.g. startup, opening a new tab by clicking the + button, hitting command-T, etc).  We want to see, among other things, how long various things take to happen after the user starts the action, which (except for startup), almost always happens in the XUL dom of the main process.  The stuff we want to compare against that includes some stuff which could probably be detected from chrome without too much trouble (eg tab visibility), as well as a bunch of stuff which happens in the page itself in a content process and can only really (as far as I know, anyway) be detected there (hero element paint, viewport painted, first interaction, etc.).  For the paint stuff, what we _really_ want is when things are actually composited such that the user sees them, but my understanding is that that's currently impractical because of content/layout/compositor architectural complexity -- so we'll settle for the paints.

> More generally, why this bug ("what are you actually trying to do?")? Do you
> think the data (what data?) you have is wrong because it looks wrong,

There are some data quality issues that we haven't sorted out yet, though these could easily be attributed to some known problems in our telemetry code unrelated to timestamp accuracy.  So partly this...

> or 'only' because you suspect there are theoretical/implementation issues with
> what you've done?

...but more this.  Initially, I was hoping to validate the existing timing mechanism with automated tests, but getting a good handle on that appears to be more difficult than I had realized.  Which is to say, there are a few specific tests for certain sorts of errors that should be doable manually, but getting solid data that is believable for the general case seems quite a bit  harder.  Before Jeff made that comment, we discussed that specific activity-stream use case in some detail in over vidyo, and came to the conclusion that things are likely "good enough" at least based on what we could reason through.

If we think this is important enough to do something about, particularly if we're expecting to try and get similar performance data across content and chrome for other UI surfaces that are in content, one thing we might be able to do is to write a JS module that exposes mozilla::Timestamp via JS-ctypes, and then expose that to specific about: pages with a new flag in AboutRedirector.cpp.

I'd love your thoughts on all this...

Comment 12

[:Gijs (he/him)]

My gut sense would be that the 'best' way of measuring this type of things would be to anchor things in one process and use messaging to ensure the 'other' timestamp is in the same process. This adds the messaging overhead (which you could try to measure by doing a second roundtrip), but it avoids pretty much all the other problems. I can't really think of a good alternative. In particular,

(In reply to Dan Mosedale (:dmose) from comment #11)
> If we think this is important enough to do something about, particularly if
> we're expecting to try and get similar performance data across content and
> chrome for other UI surfaces that are in content, one thing we might be able
> to do is to write a JS module that exposes mozilla::Timestamp via JS-ctypes,

(I'm pretty sure we'd want to use (web)idl rather than js-ctypes, but well, details, details...)

> and then expose that to specific about: pages with a new flag in
> AboutRedirector.cpp.

I'm not clear on how this would fix something here. Can you elaborate? How does mozilla::Timestamp improve things over the DOMHighResTimeStamp that the window's perf object gives you? Is it the ability to construct a timestamp at an arbitrary point in time (without a DOM window ref), or something?

And why does it need exposing to the about: page? The content process/frame scripts are privileged, so presumably can do whatever they like already (in response to hooking up the same event handlers etc.). It should be pretty trivial to expose some XPCOM thing that just returns the high res timestamp number for 'now' (or equivalent). In fact, we might already have that, I'm not sure...

I don't know if this set of questions is helpful, but they're what I have right now. From what you say, if things are "good enough" for now, maybe we don't need to do anything - but we can of course revisit later... :-)

Comment 13

[Dan Mosedale (:dmosedale, :dmose)]

(In reply to :Gijs (slow, PTO recovery mode) from comment #12)
> My gut sense would be that the 'best' way of measuring this type of things
> would be to anchor things in one process and use messaging to ensure the
> 'other' timestamp is in the same process. This adds the messaging overhead
> (which you could try to measure by doing a second roundtrip), but it avoids
> pretty much all the other problems. I can't really think of a good
> alternative. In particular,

So when we've done local profiling, even on not-terribly-slow machines,
we've seen reproducible cases where the content process was janked causing it not to service the message queue for a while.  Now presumably, since we'd want to anchor the timing in the parent process, that particular issue wouldn't be a problem, though the converse might.  Timing the messaging overhead adds a bunch more complexity, which is potentially an issue of its own, but we could indeed do it if necessary.

> (In reply to Dan Mosedale (:dmose) from comment #11)
> > If we think this is important enough to do something about, particularly if
> > we're expecting to try and get similar performance data across content and
> > chrome for other UI surfaces that are in content, one thing we might be able
> > to do is to write a JS module that exposes mozilla::Timestamp via JS-ctypes,
> 
> (I'm pretty sure we'd want to use (web)idl rather than js-ctypes, but well,
> details, details...)

Fair enough, thanks for the suggestion.

> > and then expose that to specific about: pages with a new flag in
> > AboutRedirector.cpp.
> 
> I'm not clear on how this would fix something here. Can you elaborate? How
> does mozilla::Timestamp improve things over the DOMHighResTimeStamp that the
> window's perf object gives you? Is it the ability to construct a timestamp
> at an arbitrary point in time (without a DOM window ref), or something?

No, it's because timeOrigin is based on PR_Now(), which can move around thanks to NTP, etc.  Which means that comparing the two timeOrigins (as we're doing today by adding the timeOrigin to both values) could sometimes introduce a bunch of error there.  However, for Activity Stream specifically, that may not be such a big deal, since most of the comparisons we're doing will relate to a single newtab session, which means that the all the times collected will likely have a similar amount of skew.  Of course, if we try to compute (eg) the median of all newtab sessions across a single browser session, that might cause issues, but we don't currently have a plan to do that.  I did discuss much of this stuff with Jeff before he commented here, so I'm not super concerned about this based on what he said, but it's not fantastic.
 
> And why does it need exposing to the about: page? The content process/frame
> scripts are privileged, so presumably can do whatever they like already (in
> response to hooking up the same event handlers etc.). It should be pretty
> trivial to expose some XPCOM thing that just returns the high res timestamp
> number for 'now' (or equivalent). In fact, we might already have that, I'm
> not sure...

So right now, we're doing all of our timing inside the content page itself.   I guess we could move it to framescripts, but I'm not sure what stumbling blocks we'd hit there, and it mostly seems like a sideways jump.

> I don't know if this set of questions is helpful, but they're what I have
> right now. From what you say, if things are "good enough" for now, maybe we
> don't need to do anything - but we can of course revisit later... :-)

Your thoughts have indeed been helpful; thanks!  I'll needinfo you again just in case my answers provoke any new ideas.

My current thinking is that until we have a strong reason to believe that this is causing us real life timing issues, it's worth leaving alone.  That said, we do have some data anomalies that we believe are currently caused by how we collect some of the data on the chrome side, and we're tracking that in https://github.com/mozilla/activity-stream/issues/3138.  I think the next step here is to make that high priority to fix, and then see if we still have data anomalies, and if we can't nail them down, see if we can figure out a way to decide whether this is the problem or not.

Comment 14

[:Gijs (he/him)]

Yeah, I don't have any brilliant ideas here, unfortunately. Leaving this alone until/unless there's evidence this is causing serious issues seems sane to me.

Comment 15

[Dan Mosedale (:dmosedale, :dmose)]

Closed as per comment 13 and comment 14.  We can always re-open if more information surfaces.