From 4d2944181982ecb6e5a7cfc2a7260cd07643006d Mon Sep 17 00:00:00 2001
From: Doug Thayer <dothayer@mozilla.com>
Date: Thu, 5 Sep 2019 20:02:36 +0000
Subject: [PATCH] Bug 1575610 - Revamp AsyncTabSwitcher.jsm logging r=mconley

This just adds a bit of information to the AsyncTabSwitcher's
logging and cleans up the display to make it quicker to find
what changed, especially with large numbers of tabs. The bit of
new information that I'm particularly interested in is what
event triggered a particular update - so now every time we call
postActions, we include the name of the event.

Differential Revision: https://phabricator.services.mozilla.com/D44710

--HG--
extra : moz-landing-system : lando
---
 .../docs/tabbrowser/async-tab-switcher.rst    |  18 +-
 browser/modules/AsyncTabSwitcher.jsm          | 162 ++++++++++++++----
 2 files changed, 135 insertions(+), 45 deletions(-)

diff --git a/browser/base/content/docs/tabbrowser/async-tab-switcher.rst b/browser/base/content/docs/tabbrowser/async-tab-switcher.rst
index fbeaa0988579..ab758cbd3d81 100644
--- a/browser/base/content/docs/tabbrowser/async-tab-switcher.rst
+++ b/browser/base/content/docs/tabbrowser/async-tab-switcher.rst
@@ -88,7 +88,7 @@ While the async tab switcher exists, it maps each ``<xul:tab>`` in the window to
 
    If a tab is in this state, it must have either initialized there, or transitioned from ``STATE_UNLOADING``.
 
-   When logging states, this state is indicated by the ``-`` character.
+   When logging states, this state is indicated by the ``unloaded`` string.
 
 ``STATE_LOADING``
    Layers for this ``<xul:tab>`` have not yet been reported as "received" by the compositor, but we've asked the tab to start rendering. This usually means that we want to switch to the tab, or at least to warm it up.
@@ -97,7 +97,7 @@ While the async tab switcher exists, it maps each ``<xul:tab>`` in the window to
 
    If a tab is in this state, it must have either initialized there, or transitioned from ``STATE_UNLOADED``.
 
-   When logging states, this state is indicated by the ``+?`` characters.
+   When logging states, this state is indicated by the ``loading`` string.
 
 ``STATE_LOADED``
    Layers for this ``<xul:tab>`` are available on the compositor and can be displayed. This means that the tab is either being shown to the user, or could be very quickly shown to the user.
@@ -106,7 +106,7 @@ While the async tab switcher exists, it maps each ``<xul:tab>`` in the window to
 
    When a tab is in ``STATE_LOADED``, this means that the associated ``<xul:browser>`` will have its ``renderLayers`` and ``hasLayers`` properties both return ``true``.
 
-   When logging states, this state is indicated by the ``+`` character.
+   When logging states, this state is indicated by the ``loaded`` string.
 
 ``STATE_UNLOADING``
    Layers for this ``<xul:tab>`` were at one time available on the compositor, but we've asked the tab to unload them to preserve memory. This usually means that we've switched away from this tab, or have stopped warming it up.
@@ -115,7 +115,7 @@ While the async tab switcher exists, it maps each ``<xul:tab>`` in the window to
 
    If a tab is in this state, it must have either initialized there, or transitioned from ``STATE_LOADED``.
 
-   When logging states, this state is indicated by the ``-?`` characters.
+   When logging states, this state is indicated by the ``unloading`` string.
 
 Having a tab render its layers is done by settings its state to ``STATE_LOADING``. Once the layers have been received, the switcher will automatically set the state to ``STATE_LOADED``. Similarly, telling a tab to stop rendering is done by settings its state to ``STATE_UNLOADING``. The switcher will automatically set the state to ``STATE_UNLOADED`` once the layers have fully unloaded.
 
@@ -131,7 +131,7 @@ The switcher then creates an internal mapping from ``<xul:tab>>``'s to states. T
 .. code-block:: none
 
   // This is using the logging syntax laid out in the `Tab states` section.
-  0:(+) 1:(-)
+  0:(loaded) 1:(unloaded)
 
 Be sure to refer to :ref:`async-tab-switcher.states` for an explanation of the terminology and :ref:`async-tab-switcher.logging` syntax for states.
 
@@ -143,7 +143,7 @@ Now that initialization done, the switcher is asked to request **1**. It does th
 
 .. code-block:: none
 
-  0:(+) 1:(+?)
+  0:(loaded) 1:(loading)
 
 At this point, the user is still looking at tab **0**, and none of the UI is showing any visible indication of tab change.
 
@@ -153,7 +153,7 @@ Eventually, the layers for **1** are uploaded to the compositor, and the ``<xul:
 
 .. code-block:: none
 
-  0:(+) 1:(+)
+  0:(loaded) 1:(loaded)
 
 So now layers for both **0** and **1** are uploading and available on the compositor. At this point, the switcher updates the visual state of the browser, and flips the ``<xul:deck>`` to display **1**, and the user experiences the tab switch.
 
@@ -161,7 +161,7 @@ The switcher isn't done, however. After a predefined amount of time (dictated by
 
 .. code-block:: none
 
-  0:(-?) 1:(+)
+  0:(unloading) 1:(loaded)
 
 Having requested that **0** go into ``STATE_UNLOADING``, the switcher returns back to the event loop. The user, meanwhile, continues to use ``1``.
 
@@ -169,7 +169,7 @@ Eventually, the layers for **0** are cleared from the compositor, and the ``<xul
 
 .. code-block:: none
 
-  0:(-) 1:(+)
+  0:(unloaded) 1:(loaded)
 
 The tab at **0** is now in ``STATE_UNLOADED``. Since the last requested tab **1** is in ``STATE_LOADED`` and all other background tabs are in ``STATE_UNLOADED``, the switcher decides its work is done. It deregisters its event handlers, and then destroys itself.
 
diff --git a/browser/modules/AsyncTabSwitcher.jsm b/browser/modules/AsyncTabSwitcher.jsm
index 1423428ef847..e4c73b034ae6 100644
--- a/browser/modules/AsyncTabSwitcher.jsm
+++ b/browser/modules/AsyncTabSwitcher.jsm
@@ -149,6 +149,7 @@ class AsyncTabSwitcher {
 
     this._useDumpForLogging = false;
     this._logInit = false;
+    this._logFlags = [];
 
     this.window.addEventListener("MozAfterPaint", this);
     this.window.addEventListener("MozLayerTreeReady", this);
@@ -372,19 +373,34 @@ class AsyncTabSwitcher {
       // For (2), "finished loading a non-local-about: page" is
       // determined by the busy state on the tab element and checking
       // if the loaded URI is local.
-      let hasSufficientlyLoaded =
-        !this.requestedTab.hasAttribute("busy") &&
-        !this.tabbrowser.isLocalAboutURI(requestedBrowser.currentURI);
+      let isBusy = this.requestedTab.hasAttribute("busy");
+      let isLocalAbout = this.tabbrowser.isLocalAboutURI(
+        requestedBrowser.currentURI
+      );
+      let hasSufficientlyLoaded = !isBusy && !isLocalAbout;
 
       let fl = requestedBrowser.frameLoader;
       shouldBeBlank =
         !this.minimizedOrFullyOccluded &&
         (!fl.remoteTab ||
           (!hasSufficientlyLoaded && !fl.remoteTab.hasPresented));
+
+      if (this.logging()) {
+        let flag = shouldBeBlank ? "blank" : "nonblank";
+        this.addLogFlag(
+          flag,
+          this.minimizedOrFullyOccluded,
+          fl.remoteTab,
+          isBusy,
+          isLocalAbout,
+          fl.remoteTab ? fl.remoteTab.hasPresented : 0
+        );
+      }
     }
 
-    this.log("Tab should be blank: " + shouldBeBlank);
-    this.log("Requested tab is remote?: " + requestedBrowser.isRemoteBrowser);
+    if (requestedBrowser.isRemoteBrowser) {
+      this.addLogFlag("isRemote");
+    }
 
     // Figure out which tab we actually want visible right now.
     let showTab = null;
@@ -595,7 +611,7 @@ class AsyncTabSwitcher {
   // tab. It's expected that we've already updated all the principal
   // state variables. This function takes care of updating any auxilliary
   // state.
-  postActions() {
+  postActions(eventString) {
     // Once we finish loading loadingTab, we null it out. So the state should
     // always be LOADING.
     this.assert(
@@ -688,7 +704,7 @@ class AsyncTabSwitcher {
       this.finish();
     }
 
-    this.logState("done");
+    this.logState("/" + eventString);
   }
 
   // Fires when we're ready to unload unused tabs.
@@ -699,7 +715,7 @@ class AsyncTabSwitcher {
 
     this.unloadNonRequiredTabs();
 
-    this.postActions();
+    this.postActions("onUnloadTimeout");
   }
 
   deactivateCachedBackgroundTabs() {
@@ -762,7 +778,7 @@ class AsyncTabSwitcher {
     this.logState("onLoadTimeout");
     this.preActions();
     this.maybeClearLoadTimer("onLoadTimeout");
-    this.postActions();
+    this.postActions("onLoadTimeout");
   }
 
   // Fires when the layers become available for a tab.
@@ -793,6 +809,11 @@ class AsyncTabSwitcher {
   // previously are done, so there's no need to keep the old layers
   // around.
   onPaint(event) {
+    this.addLogFlag(
+      "onPaint",
+      this.switchPaintId != -1,
+      event.transactionId >= this.switchPaintId
+    );
     if (this.switchPaintId != -1 && event.transactionId >= this.switchPaintId) {
       if (
         TelemetryStopwatch.running(
@@ -862,7 +883,7 @@ class AsyncTabSwitcher {
       // This will cause us to show a tab spinner instead.
       this.preActions();
       this.lastVisibleTab = null;
-      this.postActions();
+      this.postActions("onTabRemoved");
     }
   }
 
@@ -1103,7 +1124,7 @@ class AsyncTabSwitcher {
       unloadTimeout
     );
 
-    this.postActions();
+    this.postActions("queueUnload");
   }
 
   handleEvent(event, delayed = false) {
@@ -1145,7 +1166,7 @@ class AsyncTabSwitcher {
           break;
       }
 
-      this.postActions();
+      this.postActions(event.type);
     } finally {
       this._processing = false;
     }
@@ -1284,14 +1305,23 @@ class AsyncTabSwitcher {
     }
   }
 
-  logState(prefix) {
+  addLogFlag(flag, ...subFlags) {
+    if (this.logging()) {
+      if (subFlags.length > 0) {
+        flag += `(${subFlags.map(f => (f ? 1 : 0)).join("")})`;
+      }
+      this._logFlags.push(flag);
+    }
+  }
+
+  logState(suffix) {
     if (!this.logging()) {
       return;
     }
 
-    let accum = prefix + " ";
-    for (let i = 0; i < this.tabbrowser.tabs.length; i++) {
-      let tab = this.tabbrowser.tabs[i];
+    let getTabString = tab => {
+      let tabString = "";
+
       let state = this.getTabState(tab);
       let isWarming = this.warmingTabs.has(tab);
       let isCached = this.tabLayerCache.includes(tab);
@@ -1300,18 +1330,17 @@ class AsyncTabSwitcher {
       let isActive = linkedBrowser && linkedBrowser.docShellIsActive;
       let isRendered = linkedBrowser && linkedBrowser.renderLayers;
 
-      accum += i + ":";
       if (tab === this.lastVisibleTab) {
-        accum += "V";
+        tabString += "V";
       }
       if (tab === this.loadingTab) {
-        accum += "L";
+        tabString += "L";
       }
       if (tab === this.requestedTab) {
-        accum += "R";
+        tabString += "R";
       }
       if (tab === this.blankTab) {
-        accum += "B";
+        tabString += "B";
       }
 
       let extraStates = "";
@@ -1331,30 +1360,91 @@ class AsyncTabSwitcher {
         extraStates += "R";
       }
       if (extraStates != "") {
-        accum += `(${extraStates})`;
+        tabString += `(${extraStates})`;
       }
 
-      if (state == this.STATE_LOADED) {
-        accum += "(+)";
+      switch (state) {
+        case this.STATE_LOADED: {
+          tabString += "(loaded)";
+          break;
+        }
+        case this.STATE_LOADING: {
+          tabString += "(loading)";
+          break;
+        }
+        case this.STATE_UNLOADING: {
+          tabString += "(unloading)";
+          break;
+        }
+        case this.STATE_UNLOADED: {
+          tabString += "(unloaded)";
+          break;
+        }
       }
-      if (state == this.STATE_LOADING) {
-        accum += "(+?)";
+
+      return tabString;
+    };
+
+    let accum = "";
+
+    // This is a bit tricky to read, but what we're doing here is collapsing
+    // identical tab states down to make the overal string shorter and easier
+    // to read, and we move all simply unloaded tabs to the back of the list.
+    // I.e., we turn
+    //   "0:(unloaded) 1:(unloaded) 2:(unloaded) 3:(loaded)""
+    // into
+    //   "3:(loaded) 0...2:(unloaded)"
+    let tabStrings = this.tabbrowser.tabs.map(t => getTabString(t));
+    let lastMatch = -1;
+    let unloadedTabsStrings = [];
+    for (let i = 0; i <= tabStrings.length; i++) {
+      if (i > 0) {
+        if (i < tabStrings.length && tabStrings[i] == tabStrings[lastMatch]) {
+          continue;
+        }
+
+        if (tabStrings[lastMatch] == "(unloaded)") {
+          if (lastMatch == i - 1) {
+            unloadedTabsStrings.push(lastMatch.toString());
+          } else {
+            unloadedTabsStrings.push(`${lastMatch}...${i - 1}`);
+          }
+        } else if (lastMatch == i - 1) {
+          accum += `${lastMatch}:${tabStrings[lastMatch]} `;
+        } else {
+          accum += `${lastMatch}...${i - 1}:${tabStrings[lastMatch]} `;
+        }
       }
-      if (state == this.STATE_UNLOADED) {
-        accum += "(-)";
-      }
-      if (state == this.STATE_UNLOADING) {
-        accum += "(-?)";
-      }
-      accum += " ";
+
+      lastMatch = i;
     }
 
-    accum += "cached: " + this.tabLayerCache.length;
+    if (unloadedTabsStrings.length > 0) {
+      accum += `${unloadedTabsStrings.join(",")}:(unloaded) `;
+    }
+
+    accum += "cached: " + this.tabLayerCache.length + " ";
+
+    if (this._logFlags.length > 0) {
+      accum += `[${this._logFlags.join(",")}] `;
+      this._logFlags = [];
+    }
+
+    // It can be annoying to read through the entirety of a log string just
+    // to check if something changed or not. So if we can tell that nothing
+    // changed, just write "unchanged" to save the reader's time.
+    let logString;
+    if (this._lastLogString == accum) {
+      accum = "unchanged";
+    } else {
+      this._lastLogString = accum;
+    }
+    logString = `ATS: ${accum}{${suffix}}`;
 
     if (this._useDumpForLogging) {
-      dump(accum + "\n");
+      dump(logString + "\n");
     } else {
-      Services.console.logStringMessage(accum);
+      Services.console.logStringMessage(logString);
     }
   }
 }