820167 - Enable performance measurement of tab animation

Status: RESOLVED FIXED

(Firefox :: Tabbed Browser, defect)

Description

[Avi Halachmi (:avih)]

1. Motivation:
- Enable measurements of tab animation performance which can be used for relative comparisons (before/after specific changes).

2. Generalized goal:
- Create a facility which collects discrete performance data of frame-intervals and paint-processing (inc. layout flush) durations over determined periods of time (TBD exact collections).

3. Method:
- When enabled, a client triggers a start, the refresh driver collects {frame-interval, processing-duration} pairs.
- When a client triggers a stop, the ordered collection is returned to the client for further processing (stats, telemetry, display, etc).

4. Constraints:
- Negligible performance impact when not in enabled, minimal impact when enabled/used.
- The refresh driver shouldn't be modified when more clients use this facility.
- Some performance penalty is acceptable when returning the collected data.

5. Implementation:
- Accessible from javascript (start/stop/data-collection).
- A single cyclic buffer of pairs (possibly triplets - with timestamps) which serves as many clients as required.
  - Storage space isn't an issue: Even an hour worth of buffer @max-60-fps with 128 bytes per entry (2 doubles and a timestamp) is 60*60*60*128 = 27MB of data. Much smaller buffer can probably be used, and entry size would probably be smaller.
- When a client triggers a start, it gets a "handle" which is actually the index of current buffer position, combined with some other data which will later allow to verify that the initial position wasn't overwritten at the stop trigger (e.g. overall number of measured frames, from which start position and isOverwritten can be deduced).
- When a client triggers a stop, it provides its handle, and the refresh driver returns the chunk of pairs collected since the start position indicated by this handle.
- When the system is enabled, the buffer is used constantly, even if no client triggered a start (simpler - stateless, and better performance since no states should be managed when triggering a start).

6. Control:
- A global pref to enable this refresh driver functionality (and also allocation and usage of the buffer). E.g. toolkit.telemetry.collectFrameInfo.enabled
- Each client uses its own pref to enable itself, preferably with the same prefix as the global one, e.g. toolkit.telemetry.collectFrameInfo.tabAnimation.enabled

7. Tab specific:
- When enabled, tabbrowser.xml will collect frame info performance for tab open and tab close animations.
- Once each specific animation is done, it will print to the error console a summary of the performance (TBD, possibly discrete frame times, average FPS, average paint-processing duration).
- Possibly collect aggregate data, possibly into telemetry. TBD.

8. UI:
- Possibly an addon will be provided to control this functionality for easier usage of the UX team (instead of enabling 2 prefs).

Comment 1

[Avi Halachmi (:avih)]

vladan mentioned a very similar API at LayerManager (Start/StopFrameTimeRecording - bug 696398 by jrmuizel). Seeing that it's very similar to my WIP patch, I talked to jrmuizel and we agreed that it makes sense to combine the efforts by adding the extra measurement of this bug (flush+paint) to the frame intervals which are recorded at LayerManager.

Since LayerManager doesn't know when the layout flush starts and also can't know which refresh driver initiated it, he suggested that the painting refresh driver will update the layer manager before it triggers the flush/paint. As far as I can tell, this should also work with vlad's current timers patch of bug 731974.

However, with OMTC, a reconsideration might be required.

The existing implementation is a bit different than my approach (cyclic buffer with any number of concurrent consumers, vs growing array and a single consumer at a time of the current implementation), but these differences don't hinder tab open/close animation measurements.

So I'll work on extending the existing API with flush+paint measurements.

Comment 2

[Avi Halachmi (:avih)]

Attachment: Bug 820167 - Tab animation performance prints to error console on toolkit.telemetry.tabAnimationFrames.enabled

Attached patch for tab animation performance prints.

The start/StopFrameTimeRecording API was extended to include flush+paint processing times.

Note: Not sure how much costly are failed try/catch when toolkit.telemetry.tabAnimationFrames.enabled doesn't exist. If it's too much, we can either add this pref permanently, or cache the value at the window and make any change to it only affect new windows, or other approaches which I'm not aware of.

Here are tab open/close performance prints with this patch on 2 PCs (Windows 7 64, Aero theme enabled):
- This patch includes vlad's timing patch which landed few days ago (bug 731974).
- browser.newtab.url was set to about:blank
- Navigation toolbar is hidden.

Fast PC (i7-3630qm):
--------------------

Tab open (Frame-interval / paint-processing):
8 / 7
9 / 4
10 / 3
17 / 3
18 / 4
16 / 4
17 / 3
17 / 3
18 / 5
18 / 6
15 / 6
17 / 6
14 / 3
17 / 4
16 / 3
17 / 3

Tab close (Frame-interval / paint-processing):
16 / 5
10 / 9
7 / 3
17 / 4
16 / 3
16 / 3
18 / 3
17 / 4
17 / 4
17 / 4
16 / 4
17 / 4
16 / 4
22 / 9
15 / 7
17 / 3

Slow PC (AMD E-350):
--------------------

Tab open (Frame-interval / paint-processing):
12 / 12
37 / 21
26 / 12
15 / 12
11 / 10
11 / 9
15 / 10
19 / 9
17 / 10
19 / 9
18 / 10
18 / 10
19 / 9
17 / 10

Tab close (Frame-interval / paint-processing):
33 / 8
20 / 18
11 / 11
11 / 10
11 / 10
19 / 10
15 / 10
17 / 10
17 / 10
17 / 11
18 / 10
17 / 10
18 / 12
17 / 12
21 / 16
12 / 11

Comment 3

[Vladan Djeric (:vladan)]

Comment on attachment 692323 [details] [diff] [review]
Bug 820167 - Tab animation performance prints to error console on toolkit.telemetry.tabAnimationFrames.enabled

I'll take a look at this on the weekend, Ehsan feel free not to wait for me

Comment 4

[(no longer active)]

Comment on attachment 692323 [details] [diff] [review]
Bug 820167 - Tab animation performance prints to error console on toolkit.telemetry.tabAnimationFrames.enabled

Review of attachment 692323 [details] [diff] [review]:
-----------------------------------------------------------------

Please ask Jeff to review the next iteration of this patch.  He should have a much better idea on what's going on here.

::: browser/base/content/tabbrowser.xml
@@ +1276,5 @@
>                    tabContainer._handleNewTab(t);
>                  else {
> +                  try {
> +                    if (Services.prefs.getBoolPref("toolkit.telemetry.tabAnimationFrames.enabled")) {
> +                      window.getInterface(Ci.nsIDOMWindowUtils).startFrameTimeRecording();

You're relying on someone having called QI(nsIInterfaceRequestor), otherwise this won't work.

@@ +1278,5 @@
> +                  try {
> +                    if (Services.prefs.getBoolPref("toolkit.telemetry.tabAnimationFrames.enabled")) {
> +                      window.getInterface(Ci.nsIDOMWindowUtils).startFrameTimeRecording();
> +                    }
> +                  } catch (ex) {}

Please cache this bool pref so that you don't have to read it every time.

@@ +3525,5 @@
> +            if (Services.prefs.getBoolPref("toolkit.telemetry.tabAnimationFrames.enabled")) {
> +              let processings = {};
> +              let intervals = window.getInterface(Ci.nsIDOMWindowUtils).stopFrameTimeRecording(processings);
> +              let res = "Tab " + (tab.closing ? "close" : "open") + " (Frame-interval / paint-processing):\n";
> +              for (let ix = 0; ix < intervals.length; ix++) {

Nit: i

@@ +3528,5 @@
> +              let res = "Tab " + (tab.closing ? "close" : "open") + " (Frame-interval / paint-processing):\n";
> +              for (let ix = 0; ix < intervals.length; ix++) {
> +                res += Math.round(intervals[ix]) + " / " + Math.round(processings.value[ix]) + "\n";
> +              }
> +              Application.console.log(res);

Hmm, this is very weird...  I don't know where the output of Application.console goes to, and I'm not sure how expensive that would be.  For example, if this ends up on a console window in Windows, it's actually going to be noticeably expensive.

::: dom/interfaces/base/nsIDOMWindowUtils.idl
@@ +1062,5 @@
>    readonly attribute AString layerManagerType;
>  
>    void startFrameTimeRecording();
> +  void stopFrameTimeRecording([optional, array, size_is(frameCount)] out float frameProcessings,
> +                              [optional] out unsigned long frameCount,

Please rev the uuid.

Comment 5

[:Gavin Sharp [email: [e-mail]]]

(In reply to Ehsan Akhgari [:ehsan] from comment #4)
> > +              Application.console.log(res);
> 
> Hmm, this is very weird...  I don't know where the output of
> Application.console goes to, and I'm not sure how expensive that would be. 

It's just an old crusty way to get to Services.console.logStringMessage() - we're going to want to get rid of "Application" (a.k.a. "FUEL") at some point, we shouldn't extend use of it.

Comment 6

[Avi Halachmi (:avih)]

(In reply to Ehsan Akhgari [:ehsan] from comment #4)
> Hmm, this is very weird...  I don't know where the output of
> Application.console goes to, and I'm not sure how expensive that would be. 
> For example, if this ends up on a console window in Windows, it's actually
> going to be noticeably expensive.

It goes as a message to the error console, but I'll change the call. As for the cost, since this is intended for immediate feedback on animation performance but it's typically off for users, I thought the print cost is acceptable, as it happens after the animation ends.

I'll address the comments. Thanks.

Comment 7

[Avi Halachmi (:avih)]

Attachment: Bug 820167 v2 - Tab animation performance prints to error console on toolkit.telemetry.tabAnimationFrames.enabled

Addressed review issues from comment #4, except for the performance penalty of the console output which I addressed on comment #6.

Comment 8

[Jeff Muizelaar [:jrmuizel]]

Comment on attachment 692748 [details] [diff] [review]
Bug 820167 v2 - Tab animation performance prints to error console on toolkit.telemetry.tabAnimationFrames.enabled

Review of attachment 692748 [details] [diff] [review]:
-----------------------------------------------------------------

::: browser/base/content/tabbrowser.xml
@@ +1274,5 @@
>                setTimeout(function (tabContainer) {
>                  if (t.pinned)
>                    tabContainer._handleNewTab(t);
>                  else {
> +                  t._framesTelemetryEnabled = tabContainer._cachedTabFramesTelemetryPref;

You may want a better name than framesTelemetryEnabled as this could be confused with the histogram telemetry. How about calling the pref "browser.tabs.animationLogging" and renaming the associated variables.

::: dom/base/nsDOMWindowUtils.cpp
@@ +2155,5 @@
>    return NS_OK;
>  }
>  
>  NS_IMETHODIMP
> +nsDOMWindowUtils::StopFrameTimeRecording(float** processings, uint32_t *frameCount, float **frames)

I'd suggest calling these paintTimes and frameTimes instead of processings and frames.

@@ +2184,5 @@
>    if (*frameCount != 0) {
>      *frames = (float*)nsMemory::Alloc(*frameCount * sizeof(float*));
>      if (!*frames)
>        return NS_ERROR_OUT_OF_MEMORY;
> +    

extra white space here.

::: gfx/layers/Layers.h
@@ +482,5 @@
>    void LogSelf(const char* aPrefix="");
>  
>    void StartFrameTimeRecording();
> +  void StopFrameTimeRecording(nsTArray<float>& aFrameTimes, nsTArray<float>& aProcessingTimes);
> +  void SetPreFlushTime(TimeStamp& aTime);

Let's call this SetPaintStartTime

Comment 9

[Avi Halachmi (:avih)]

Attachment: Bug 820167 v3 - Tab animation performance prints to error console on toolkit.telemetry.tabAnimationFrames.enabled

Address review issues from comment #8.

Comment 10

[Avi Halachmi (:avih)]

Attachment: Bug 820167 v4 - Tab animation performance prints to error console on browser.tabs.animationLogging

Updated commit message and patch description with new pref name.

Comment 11

[Vladan Djeric (:vladan)]

Comment on attachment 693012 [details] [diff] [review]
Bug 820167 v4 - Tab animation performance prints to error console on browser.tabs.animationLogging

https://hg.mozilla.org/integration/mozilla-inbound/rev/e14c7409ede7

Comment 12

[Dão Gottwald [:dao]]

Backed out. This hasn't been reviewed by a browser peer.

https://hg.mozilla.org/integration/mozilla-inbound/rev/187284035437

Comment 13

[Vladan Djeric (:vladan)]

Comment on attachment 693012 [details] [diff] [review]
Bug 820167 v4 - Tab animation performance prints to error console on browser.tabs.animationLogging

(In reply to Dão Gottwald [:dao] from comment #12)
> Backed out. This hasn't been reviewed by a browser peer.
> 
> https://hg.mozilla.org/integration/mozilla-inbound/rev/187284035437

Ehsan did one review pass of this and turned it over to Jeff before he went on PTO. Could we ask you to re-review the browser part?

Comment 14

[Dão Gottwald [:dao]]

Comment on attachment 693012 [details] [diff] [review]
Bug 820167 v4 - Tab animation performance prints to error console on browser.tabs.animationLogging

>+              window.QueryInterface(Components.interfaces.nsIInterfaceRequestor)
>+              .getInterface(Components.interfaces.nsIDOMWindowUtils)
>+              .startFrameTimeRecording();

use Ci instead of Components.interfaces and indent the second and third line with another six spaces each

>+          try {
>+            this._cachedTabAnimationLoggingPref = Services.prefs.getBoolPref("browser.tabs.animationLogging");
>+          } catch (ex) {
>+            this._cachedTabAnimationLoggingPref = false;
>+          }

rename this to _tabAnimationLoggingEnabled

>+          if (tab._animationLoggingEnabled) {
>+            let paints = {};

use this._tabAnimationLoggingEnabled here; tab._animationLoggingEnabled is redundant and can go away, as far as I can see.

Comment 15

[Dão Gottwald [:dao]]

Does this patch handle two tabs being animated concurrently? Do you not care about this case, since you assume that only developers will set this pref?

Comment 16

[Avi Halachmi (:avih)]

Attachment: Bug 820167 v5 - Tab open/close animation performance prints to error console when enabled

Address review issues from comment #14. Thanks for noticing the redundancy.

(In reply to Dão Gottwald [:dao] from comment #15)
> Does this patch handle two tabs being animated concurrently? Do you not care
> about this case, since you assume that only developers will set this pref?

This bug was filed in response to bug 815354 and provides the required measurements for it.

The patch measures only tab open/close animation of this tab (and doesn't measure, for example, when a new tab appears without animation and the whole tabstrip is scrolled to bring the new tab into view).

However, it is true that the bug title is not accurate. Please advise on this.

As for concurrent measurements, while the underlying infrastructure doesn't currently support multiple concurrent consumers, I believe it's not required for tabstrip animations, since even if tabs are animated concurrently, they will all show the same measurements (same frame interval and same paint duration for all the tabs which were animating at that frame).

This can be seen, e.g. when a new tab opens in animation while all other tabs shrink simultaneously -> paint times and possibly frame rates (measured for the new tab) correspond to the overall paint/layout-changes load and therefore suffer compared to when only one tab opens and the other tabs don't change.

The obvious case which this patch doesn't measured is therefore when a new tab appears without animation and the tabstrip scrolls to bring it into view (this is not the case for tab close, which currently animates even if the rest of the tabstrip scrolls as a result).

Less obvious cases are if some animations start before the tab animation starts or end after the tab animation ends (and therefore outside of the patch's measurements). I don't know if there are such cases.

I'm not currently aware of other tabstrip animations which don't coincide with tab open/close animations other than the tab-doesn't-animate-and-tabstrip-scrolls case.

Comment 17

[Dão Gottwald [:dao]]

Comment on attachment 693213 [details] [diff] [review]
Bug 820167 v5 - Tab open/close animation performance prints to error console when enabled

r=me for the browser/ part

Comment 18

[Vladan Djeric (:vladan)]

Comment on attachment 693213 [details] [diff] [review]
Bug 820167 v5 - Tab open/close animation performance prints to error console when enabled

https://hg.mozilla.org/integration/mozilla-inbound/rev/9864a836aa35

r=jmuizelaar for gfx parts
r=dao for front-end parts

All the DOM code changed was written by Jeff

Comment 19

[Ed Morley [:emorley]]

Backed out for crashes:
https://tbpl.mozilla.org/?tree=Mozilla-Inbound&rev=9864a836aa35

https://hg.mozilla.org/integration/mozilla-inbound/rev/cc6f68c9a929

Comment 20

[Avi Halachmi (:avih)]

Attachment: v6 - disable the paint-times recording part on android

I'm not requesting a review for now, to see if bug 785597 lands soon. If it doesn't, then I hope to land it as is since I think it may still serve well on platforms other than android, and enable it on android when it doesn't crash anymore.

This patch eliminates the android crashes: https://tbpl.mozilla.org/?tree=Try&rev=18cfa1078e09

Comment 21

[Vladan Djeric (:vladan)]

Comment on attachment 694543 [details] [diff] [review]
v6 - disable the paint-times recording part on android

https://hg.mozilla.org/integration/mozilla-inbound/rev/68f26a077cee

Comment 22

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/68f26a077cee