Categories

(Firefox :: General, defect)

Tracking

(bug RESOLVED as FIXED)

People

(Reporter: vladan, Assigned: chutten|PTO)

References

Details

EVENTLOOP_UI_ACTIVITY_EXP_MS should get collected in child processes as well

At present, it's the nsWindow::WindowProc (widget/windows/nsWindow.cpp) that calls NotifyActivity with kUIActivity. So this should be happening not only for each process, but for each window in each process.

...but it isn't being called in the child process. Odd. Time to talk to #e10s folks.

Interesting.

1) This probe is Windows-only. Not sure why (the presence of high-resolution timers?), but it's only in widget/windows/nsWindow

2) This probe measures all events coming in to the application. We ask the platform for events over the whole area to be sent to the parent process, which (for Windows) does the WindowProc thing and eventually chooses which process to dispatch to via PBrowser.ipdl and PContent.ipdl (which means that, with a child process paused, you can still do APZ scrolling (but anything not painted will never paint))

3) Not only that, but since UI events are dispatched synchronously (prio(high) sync DispatchMouseEvent(WidgetMouseEvent event);) we're measuring how long they take appropriately as well.

4) Since all UI events come through the parent process and are handled synchronously, a slowdown in the content will still slow down the parent. And vice versa. When it comes to responsiveness (as measured by this probe) the two process types are still joined at the hip.

We could add a probe a little further down that distinguishes between PBrowser and PContent dispatches if we wanted to measure how much this hip-attachment is hurting users... but otherwise, I don't think this bug can be acted on.

(thanks to :jimm for helping me out)

Okay, ignore most of comment #2 as the synchronous dispatch isn't used on Desktop (why do we have that lever?).

Hey felipe, now that we've sorted out that events are being dispatched asynchronously, the perf team wants to find a way of measuring how long it takes for an event to be consumed by the content process.

How easy / advisable would it be, in your opinion, to decorate the event with a timestamp on consumption in the parent process, and then take the delta between now and that timestamp in the content process when the event is eventually consumed to report to Telemetry?

If you do that, you may need to make sure that the clock is the same on both processes, which is more annoying than it looks. It might be easier to send a delta already from the parent to the child, and just sum the deltas.

Do we trust TimeStamp cross-process? 

WidgetGUIEvent.time is init'd (in nsWindow::InitEvent) to ::GetMessageTime (which is millis since boot up to the message being created by the OS and put on our queue), and WidgetGUIEvent.timeStamp is our TimeStamp of the same moment in time.

According to :vlad and :Yoric, TimeStamps should be able to be passed across processes in Windows, Linux, and Darwin and be sensible to TimeStamps generated on the other end. (in other words, if you generate a TimeStamp at t=1 on the parent and t=1 on the child, then the two should be roughly equal on the three main Desktop platforms). Which is good! This means that we can use a WidgetGUIEvent.timeStamp that was set on the parent process to calculate a duration on the child process.

Support across the ports is currently mixed.

As stated in comment 6, Windows gives us a useful event time that we convert to a TimeStamp. This should give us coverage analogous to the current approach, but measured completely differently.

For the gtk port we use GdkEvent.time which is a little less specified (what is 'the time of the event' anyway?), but should be consistent. (maybe just don't try to compare Linux's times to other platforms)

All other ports currently do not set WidgetGUIEvent.timeStamp. It didn't take me long to find cocoa's NSEvent.timeStamp (which we currently only seem to use for async scroll events), so I'm sure someone who wanted to file and fix a bug to populate timeStamp on cocoa wouldn't be busy for long.

(clearing the needinfo as I talked to chutten on IRC about this)

I think this neendinfo request is no longer relevant, in light of comment 3

Adds a new histogram INPUT_EVENT_RESPONSE_MS that uses underlying OS timestamps to calculate how long it takes to get from the user taking an action to a process being done processing it.

Works on gtk, Windows. I've filed bug 1240539 for cocoa.

Comment on attachment 8709072 [details] [diff] [review]
0001-bug-1235908-measure-total-event-wait-and-process-tim.patch

I think I'd prefer also
Telemetry::CanRecordBase() check in the 'if'.
::Now() has been surprisingly slow.

https://hg.mozilla.org/mozilla-central/rev/677e9cf53757

Comment on attachment 8709135 [details] [diff] [review]
0001-bug-1235908-measure-total-event-wait-and-process-tim.patch

Approval Request Comment
[Feature/regressing bug #]: N/A
[User impact if declined]: If we don't have this in aurora, our next E10s experiment will have to rely on measures of responsiveness that don't have the full picture. For the first time we'll have direct information about how long users have to wait for their actions to be interpreted across processes... unless this is declined.
[Describe test coverage new/current, TreeHerder]: It populates histograms appropriately in about:telemetry, and has generated no test failures on its run into mozilla-central.
[Risks and why]: There is a small performance impact in that this patch adds code to the main thread. Similar code has been measured to be quite quick (less than 12us) and this code is guarded to run only if Telemetry is enabled, there is valid timestamp information in the event, and if the event is an input event.
[String/UUID change made/needed]: None

Comment on attachment 8709135 [details] [diff] [review]
0001-bug-1235908-measure-total-event-wait-and-process-tim.patch

Let's try it.

[bugday-20160323]

Status: RESOLVED,FIXED -> UNVERIFIED

Comments:
STR: Not clear.
Developer specific testing

Component: 
Name			Firefox
Version			46.0b9
Build ID		20160322075646
Update Channel          beta
User Agent		Mozilla/5.0 (Windows NT 6.1; WOW64; rv:46.0) Gecko/20100101 Firefox/46.0
OS			Windows 7 SP1 x86_64

Expected Results: 
Developer specific testing

Actual Results: 
As expected