Bug 1156592 - Record tab switch times under e10s and add support for debug console logging tied to a hidden pref. r=billm
authorJim Mathies <jmathies@mozilla.com>
Thu, 30 Apr 2015 14:42:43 -0500
changeset 273287 3265c932f222e8ffb93de7b2fd8173484cc89ee6
parent 273286 37bab93f427e7e8b141ed0ac26c8e21e1a031128
child 273288 31297813dd26df515d5b388e7f1faad00724cd33
push id863
push userraliiev@mozilla.com
push dateMon, 03 Aug 2015 13:22:43 +0000
treeherdermozilla-release@f6321b14228d [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersbillm
bugs1156592
milestone40.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1156592 - Record tab switch times under e10s and add support for debug console logging tied to a hidden pref. r=billm
browser/base/content/tabbrowser.xml
--- a/browser/base/content/tabbrowser.xml
+++ b/browser/base/content/tabbrowser.xml
@@ -1030,18 +1030,22 @@
         <body>
           <![CDATA[
             var newBrowser = this.getBrowserAtIndex(this.tabContainer.selectedIndex);
             if (this.mCurrentBrowser == newBrowser && !aForceUpdate)
               return;
 
             if (!aForceUpdate) {
               TelemetryStopwatch.start("FX_TAB_SWITCH_UPDATE_MS");
-              window.QueryInterface(Ci.nsIInterfaceRequestor).getInterface(Ci.nsIDOMWindowUtils)
-                                                             .beginTabSwitch();
+              if (!Services.appinfo.browserTabsRemoteAutostart) {
+                // old way of measuring tab paint which is not
+                // valid with e10s.
+                window.QueryInterface(Ci.nsIInterfaceRequestor).getInterface(Ci.nsIDOMWindowUtils)
+                                                               .beginTabSwitch();
+              }
             }
 
             var oldTab = this.mCurrentTab;
 
             // Preview mode should not reset the owner
             if (!this._previewMode && !oldTab.selected)
               oldTab.owner = null;
 
@@ -2980,18 +2984,16 @@
             // removed from the set upon MozAfterPaint.
             maybeVisibleTabs: new Set([this.selectedTab]),
 
             STATE_UNLOADED: 0,
             STATE_LOADING: 1,
             STATE_LOADED: 2,
             STATE_UNLOADING: 3,
 
-            logging: false,
-
             getTabState: function(tab) {
               let state = this.tabState.get(tab);
               if (state === undefined) {
                 return this.STATE_UNLOADED;
               }
               return state;
             },
 
@@ -3083,26 +3085,28 @@
               } else {
                 // Show the requested tab. If it's not available, we'll show the spinner.
                 showTab = this.requestedTab;
               }
 
               // Show or hide the spinner as needed.
               let needSpinner = this.getTabState(showTab) != this.STATE_LOADED;
               if (!needSpinner && this.spinnerTab) {
+                this.spinnerHidden();
                 this.tabbrowser.removeAttribute("pendingpaint");
                 this.spinnerTab.linkedBrowser.removeAttribute("pendingpaint");
                 this.spinnerTab = null;
               } else if (needSpinner && this.spinnerTab !== showTab) {
                 if (this.spinnerTab) {
                   this.spinnerTab.linkedBrowser.removeAttribute("pendingpaint");
                 }
                 this.spinnerTab = showTab;
                 this.tabbrowser.setAttribute("pendingpaint", "true");
                 this.spinnerTab.linkedBrowser.setAttribute("pendingpaint", "true");
+                this.spinnerDisplayed();
               }
 
               // Switch to the tab we've decided to make visible.
               if (this.visibleTab !== showTab) {
                 this.visibleTab = showTab;
 
                 this.maybeVisibleTabs.add(showTab);
 
@@ -3275,16 +3279,17 @@
               }
             },
 
             // Fires when we paint the screen. Any tab switches we initiated
             // previously are done, so there's no need to keep the old layers
             // around.
             onPaint: function() {
               this.maybeVisibleTabs.clear();
+              this.finishTabSwitch();
             },
 
             // Called when we're done clearing the layers for a tab.
             onLayersCleared: function(browser) {
               this.logState("onLayersCleared");
 
               let tab = this.tabbrowser.getTabForBrowser(browser);
               if (tab) {
@@ -3308,16 +3313,17 @@
 
             // Called when the user asks to switch to a given tab.
             requestTab: function(tab) {
               if (tab === this.requestedTab) {
                 return;
               }
 
               this.logState("requestTab " + this.tinfo(tab));
+              this.startTabSwitch();
 
               this.requestedTab = tab;
 
               this.preActions();
 
               clearTimeout(this.unloadTimer);
               this.unloadTimer = setTimeout(() => this.onUnloadTimeout(), this.UNLOAD_DELAY);
 
@@ -3335,50 +3341,114 @@
                 this.onLayersCleared(event.originalTarget);
               } else if (event.type == "TabRemotenessChange") {
                 this.onRemotenessChange(event.target);
               }
 
               this.postActions();
             },
 
+            /*
+             * Telemetry related helpers for recording tab switch timing.
+             */
+
+            startTabSwitch: function () {
+              TelemetryStopwatch.start("FX_TAB_SWITCH_TOTAL_E10S_MS", window);
+            },
+
+            finishTabSwitch: function () {
+              if (this.requestedTab && this.getTabState(this.requestedTab) == this.STATE_LOADED) {
+                let time = TelemetryStopwatch.timeElapsed("FX_TAB_SWITCH_TOTAL_E10S_MS", window);
+                if (time != -1) {
+                  TelemetryStopwatch.finish("FX_TAB_SWITCH_TOTAL_E10S_MS", window);
+                  this.log("DEBUG: tab switch time = " + time);
+                }
+              }
+            },
+
+            spinnerDisplayed: function () {
+              if (this.spinnerTab) {
+                TelemetryStopwatch.start("FX_TAB_SWITCH_SPINNER_VISIBLE_MS", window);
+              }
+            },
+
+            spinnerHidden: function () {
+              if (this.spinnerTab) {
+                this.log("DEBUG: spinner time = " +
+                         TelemetryStopwatch.timeElapsed("FX_TAB_SWITCH_SPINNER_VISIBLE_MS", window));
+                TelemetryStopwatch.finish("FX_TAB_SWITCH_SPINNER_VISIBLE_MS", window);
+                // we do not get a onPaint after displaying the spinner
+                this.finishTabSwitch();
+              }
+            },
+
+            /*
+             * Debug related logging for switcher.
+             */
+
+            _useDumpForLogging: false,
+            _logInit: false,
+
+            logging: function () {
+              if (this._useDumpForLogging)
+                return true;
+              if (this._logInit)
+                return this._shouldLog;
+              let result = false;
+              try {
+                result = Services.prefs.getBoolPref("browser.tabs.remote.logSwitchTiming");
+              } catch (ex) {
+              }
+              this._shouldLog = result;
+              this._logInit = true;
+              return this._shouldLog;
+            },
+
             tinfo: function(tab) {
               if (tab) {
                 return tab._tPos + "(" + tab.linkedBrowser.currentURI.spec + ")";
               } else {
                 return "null";
               }
             },
 
             log: function(s) {
-              if (!this.logging)
+              if (!this.logging())
                 return;
-              dump(s + "\n");
+              if (this._useDumpForLogging) {
+                dump(s + "\n");
+              } else {
+                Services.console.logStringMessage(s);
+              }
             },
 
             logState: function(prefix) {
-              if (!this.logging)
+              if (!this.logging())
                 return;
 
-              dump(prefix + " ");
+              let accum = prefix + " ";
               for (let i = 0; i < this.tabbrowser.tabs.length; i++) {
                 let tab = this.tabbrowser.tabs[i];
                 let state = this.getTabState(tab);
 
-                dump(i + ":");
+                accum += i + ":";
                 if (tab === this.lastVisibleTab) dump("V");
                 if (tab === this.loadingTab) dump("L");
                 if (tab === this.requestedTab) dump("R");
                 if (state == this.STATE_LOADED) dump("(+)");
                 if (state == this.STATE_LOADING) dump("(+?)");
                 if (state == this.STATE_UNLOADED) dump("(-)");
                 if (state == this.STATE_UNLOADING) dump("(-?)");
-                dump(" ");
+                accum += " ";
               }
-              dump("\n");
+              if (this._useDumpForLogging) {
+                dump(accum + "\n");
+              } else {
+                Services.console.logStringMessage(accum);
+              }
             },
           };
           this._switcher = switcher;
           switcher.init();
           return switcher;
         ]]></body>
       </method>