Bug 1045715 - Make console output faster by destroying unprinted items out of band in _flushMessageQueue. r=past
authorBrian Grinstead <bgrinstead@mozilla.com>
Tue, 02 Sep 2014 06:56:00 +0200
changeset 203417 505529c35c7f029a85629306353b88011bb2cee8
parent 203416 b2cfd9248bd2db7b2f7f5026ad7ff7a8b1acc877
child 203418 518ad95704fc2214eb2b9e5d016df007f32c9df9
push id48665
push userryanvm@gmail.com
push dateWed, 03 Sep 2014 20:40:15 +0000
treeherdermozilla-inbound@0da762e6868a [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerspast
bugs1045715
milestone35.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 1045715 - Make console output faster by destroying unprinted items out of band in _flushMessageQueue. r=past
browser/devtools/webconsole/webconsole.js
--- a/browser/devtools/webconsole/webconsole.js
+++ b/browser/devtools/webconsole/webconsole.js
@@ -142,23 +142,28 @@ const MAX_HTTP_ERROR_CODE = 599;
 // Constants used for defining the direction of JSTerm input history navigation.
 const HISTORY_BACK = -1;
 const HISTORY_FORWARD = 1;
 
 // The indent of a console group in pixels.
 const GROUP_INDENT = 12;
 
 // The number of messages to display in a single display update. If we display
-// too many messages at once we slow the Firefox UI too much.
+// too many messages at once we slow down the Firefox UI too much.
 const MESSAGES_IN_INTERVAL = DEFAULT_LOG_LIMIT;
 
 // The delay between display updates - tells how often we should *try* to push
 // new messages to screen. This value is optimistic, updates won't always
 // happen. Keep this low so the Web Console output feels live.
-const OUTPUT_INTERVAL = 50; // milliseconds
+const OUTPUT_INTERVAL = 20; // milliseconds
+
+// The maximum amount of time that can be spent doing cleanup inside of the
+// flush output callback.  If things don't get cleaned up in this time,
+// then it will start again the next time it is called.
+const MAX_CLEANUP_TIME = 10; // milliseconds
 
 // When the output queue has more than MESSAGES_IN_INTERVAL items we throttle
 // output updates to this number of milliseconds. So during a lot of output we
 // update every N milliseconds given here.
 const THROTTLE_UPDATES = 1000; // milliseconds
 
 // The preference prefix for all of the Web Console filters.
 const FILTER_PREFS_PREFIX = "devtools.webconsole.filter.";
@@ -185,16 +190,17 @@ const PREF_MESSAGE_TIMESTAMP = "devtools
 function WebConsoleFrame(aWebConsoleOwner)
 {
   this.owner = aWebConsoleOwner;
   this.hudId = this.owner.hudId;
   this.window = this.owner.iframeWindow;
 
   this._repeatNodes = {};
   this._outputQueue = [];
+  this._itemDestroyQueue = [];
   this._pruneCategoriesQueue = {};
   this._networkRequests = {};
   this.filterPrefs = {};
 
   this.output = new ConsoleOutput(this);
 
   this._toggleFilter = this._toggleFilter.bind(this);
   this._onPanelSelected = this._onPanelSelected.bind(this);
@@ -2043,92 +2049,104 @@ WebConsoleFrame.prototype = {
     if (!this._outputQueue.length) {
       // If the queue is empty we consider that now was the last output flush.
       // This avoid an immediate output flush when the timer executes.
       this._lastOutputFlush = Date.now();
     }
 
     this._outputQueue.push([aCategory, aMethodOrNode, aArguments]);
 
-    if (!this._outputTimerInitialized) {
-      this._initOutputTimer();
-    }
+    this._initOutputTimer();
   },
 
   /**
    * Try to flush the output message queue. This takes the messages in the
    * output queue and displays them. Outputting stops at MESSAGES_IN_INTERVAL.
    * Further output is queued to happen later - see OUTPUT_INTERVAL.
    *
    * @private
    */
   _flushMessageQueue: function WCF__flushMessageQueue()
   {
+    this._outputTimerInitialized = false;
     if (!this._outputTimer) {
       return;
     }
 
-    let timeSinceFlush = Date.now() - this._lastOutputFlush;
-    if (this._outputQueue.length > MESSAGES_IN_INTERVAL &&
-        timeSinceFlush < THROTTLE_UPDATES) {
-      this._initOutputTimer();
-      return;
-    }
+    let startTime = Date.now();
+    let timeSinceFlush = startTime - this._lastOutputFlush;
+    let shouldThrottle = this._outputQueue.length > MESSAGES_IN_INTERVAL &&
+        timeSinceFlush < THROTTLE_UPDATES;
 
     // Determine how many messages we can display now.
     let toDisplay = Math.min(this._outputQueue.length, MESSAGES_IN_INTERVAL);
-    if (toDisplay < 1) {
-      this._outputTimerInitialized = false;
+
+    // If there aren't any messages to display (because of throttling or an
+    // empty queue), then take care of some cleanup. Destroy items that were
+    // pruned from the outputQueue before being displayed.
+    if (shouldThrottle || toDisplay < 1) {
+      while (this._itemDestroyQueue.length) {
+        if ((Date.now() - startTime) > MAX_CLEANUP_TIME) {
+          break;
+        }
+        this._destroyItem(this._itemDestroyQueue.pop());
+      }
+
+      this._initOutputTimer();
       return;
     }
 
     // Try to prune the message queue.
     let shouldPrune = false;
     if (this._outputQueue.length > toDisplay && this._pruneOutputQueue()) {
       toDisplay = Math.min(this._outputQueue.length, toDisplay);
       shouldPrune = true;
     }
 
     let batch = this._outputQueue.splice(0, toDisplay);
-    if (!batch.length) {
-      this._outputTimerInitialized = false;
-      return;
-    }
-
     let outputNode = this.outputNode;
     let lastVisibleNode = null;
     let scrollNode = outputNode.parentNode;
-    let scrolledToBottom = Utils.isOutputScrolledToBottom(outputNode);
     let hudIdSupportsString = WebConsoleUtils.supportsString(this.hudId);
 
+    // We won't bother to try to restore scroll position if this is showing
+    // a lot of messages at once (and there are still items in the queue).
+    // It is going to purge whatever you were looking at anyway.
+    let scrolledToBottom = shouldPrune ||
+                           Utils.isOutputScrolledToBottom(outputNode);
+
     // Output the current batch of messages.
     let newMessages = new Set();
     let updatedMessages = new Set();
-    for (let item of batch) {
+    for (let i = 0; i < batch.length; i++) {
+      let item = batch[i];
       let result = this._outputMessageFromQueue(hudIdSupportsString, item);
       if (result) {
         if (result.isRepeated) {
           updatedMessages.add(result.isRepeated);
         }
         else {
           newMessages.add(result.node);
         }
         if (result.visible && result.node == this.outputNode.lastChild) {
           lastVisibleNode = result.node;
         }
       }
     }
 
     let oldScrollHeight = 0;
-
-    // Prune messages if needed. We do not do this for every flush call to
-    // improve performance.
     let removedNodes = 0;
+
+    // Prune messages from the DOM, but only if needed.
     if (shouldPrune || !this._outputQueue.length) {
-      oldScrollHeight = scrollNode.scrollHeight;
+      // Only bother measuring the scrollHeight if not scrolled to bottom,
+      // since the oldScrollHeight will not be used if it is.
+      if (!scrolledToBottom) {
+        oldScrollHeight = scrollNode.scrollHeight;
+      }
 
       let categories = Object.keys(this._pruneCategoriesQueue);
       categories.forEach(function _pruneOutput(aCategory) {
         removedNodes += this.pruneOutputIfNecessary(aCategory);
       }, this);
       this._pruneCategoriesQueue = {};
     }
 
@@ -2151,37 +2169,41 @@ WebConsoleFrame.prototype = {
 
     if (newMessages.size) {
       this.emit("messages-added", newMessages);
     }
     if (updatedMessages.size) {
       this.emit("messages-updated", updatedMessages);
     }
 
-    // If the queue is not empty, schedule another flush.
-    if (this._outputQueue.length > 0) {
-      this._initOutputTimer();
-    }
-    else {
-      this._outputTimerInitialized = false;
-      if (this._flushCallback && this._flushCallback() === false) {
+    // If the output queue is empty, then run _flushCallback.
+    if (this._outputQueue.length === 0 && this._flushCallback) {
+      if (this._flushCallback() === false) {
         this._flushCallback = null;
       }
     }
 
+    this._initOutputTimer();
+
     this._lastOutputFlush = Date.now();
   },
 
   /**
    * Initialize the output timer.
    * @private
    */
   _initOutputTimer: function WCF__initOutputTimer()
   {
-    if (!this._outputTimer) {
+    let panelIsDestroyed = !this._outputTimer;
+    let alreadyScheduled = this._outputTimerInitialized;
+    let nothingToDo = !this._itemDestroyQueue.length &&
+                      !this._outputQueue.length;
+
+    // Don't schedule a callback in the following cases:
+    if (panelIsDestroyed || alreadyScheduled || nothingToDo) {
       return;
     }
 
     this._outputTimerInitialized = true;
     this._outputTimer.initWithCallback(this._flushMessageQueue,
                                        OUTPUT_INTERVAL,
                                        Ci.nsITimer.TYPE_ONE_SHOT);
   },
@@ -2269,37 +2291,38 @@ WebConsoleFrame.prototype = {
     // Loop through the categories we found and prune if needed.
     for (let category in nodes) {
       let limit = Utils.logLimitForCategory(category);
       let indexes = nodes[category];
       if (indexes.length > limit) {
         let n = Math.max(0, indexes.length - limit);
         pruned += n;
         for (let i = n - 1; i >= 0; i--) {
-          this._pruneItemFromQueue(this._outputQueue[indexes[i]]);
+          this._itemDestroyQueue.push(this._outputQueue[indexes[i]]);
           this._outputQueue.splice(indexes[i], 1);
         }
       }
     }
 
     return pruned;
   },
 
   /**
-   * Prune an item from the output queue.
+   * Destroy an item that was once in the outputQueue but isn't needed
+   * after all.
    *
    * @private
    * @param array aItem
-   *        The item you want to remove from the output queue.
+   *        The item you want to destroy.  Does not remove it from the output
+   *        queue.
    */
-  _pruneItemFromQueue: function WCF__pruneItemFromQueue(aItem)
+  _destroyItem: function WCF__destroyItem(aItem)
   {
     // TODO: handle object releasing in a more elegant way once all console
     // messages use the new API - bug 778766.
-
     let [category, methodOrNode, args] = aItem;
     if (typeof methodOrNode != "function" && methodOrNode._objectActors) {
       for (let actor of methodOrNode._objectActors) {
         this._releaseObject(actor);
       }
       methodOrNode._objectActors.clear();
     }
 
@@ -2365,19 +2388,17 @@ WebConsoleFrame.prototype = {
    *         The number of removed nodes.
    */
   pruneOutputIfNecessary: function WCF_pruneOutputIfNecessary(aCategory)
   {
     let logLimit = Utils.logLimitForCategory(aCategory);
     let messageNodes = this.outputNode.querySelectorAll(".message[category=" +
                        CATEGORY_CLASS_FRAGMENTS[aCategory] + "]");
     let n = Math.max(0, messageNodes.length - logLimit);
-    let toRemove = Array.prototype.slice.call(messageNodes, 0, n);
-    toRemove.forEach(this.removeOutputMessage, this);
-
+    [...messageNodes].slice(0, n).forEach(this.removeOutputMessage, this);
     return n;
   },
 
   /**
    * Remove a given message from the output.
    *
    * @param nsIDOMNode aNode
    *        The message node you want to remove.
@@ -2410,19 +2431,17 @@ WebConsoleFrame.prototype = {
     else if (aNode.classList.contains("inlined-variables-view")) {
       let view = aNode._variablesView;
       if (view) {
         view.controller.releaseActors();
       }
       aNode._variablesView = null;
     }
 
-    if (aNode.parentNode) {
-      aNode.parentNode.removeChild(aNode);
-    }
+    aNode.remove();
   },
 
   /**
    * Given a category and message body, creates a DOM node to represent an
    * incoming message. The timestamp is automatically added.
    *
    * @param number aCategory
    *        The category of the message: one of the CATEGORY_* constants.
@@ -2892,26 +2911,28 @@ WebConsoleFrame.prototype = {
     let toolbox = gDevTools.getToolbox(this.owner.target);
     if (toolbox) {
       toolbox.off("webconsole-selected", this._onPanelSelected);
     }
 
     gDevTools.off("pref-changed", this._onToolboxPrefChanged);
 
     this._repeatNodes = {};
+    this._outputQueue.forEach(this._destroyItem, this);
     this._outputQueue = [];
+    this._itemDestroyQueue.forEach(this._destroyItem, this);
+    this._itemDestroyQueue = [];
     this._pruneCategoriesQueue = {};
     this._networkRequests = {};
 
     if (this._outputTimerInitialized) {
       this._outputTimerInitialized = false;
       this._outputTimer.cancel();
     }
     this._outputTimer = null;
-
     if (this.jsterm) {
       this.jsterm.destroy();
       this.jsterm = null;
     }
     this.output.destroy();
     this.output = null;
 
     if (this._contextMenuHandler) {
@@ -3782,17 +3803,17 @@ JSTerm.prototype = {
     let hud = this.hud;
     let outputNode = hud.outputNode;
     let node;
     while ((node = outputNode.firstChild)) {
       hud.removeOutputMessage(node);
     }
 
     hud.groupDepth = 0;
-    hud._outputQueue.forEach(hud._pruneItemFromQueue, hud);
+    hud._outputQueue.forEach(hud._destroyItem, hud);
     hud._outputQueue = [];
     hud._networkRequests = {};
     hud._repeatNodes = {};
 
     if (aClearStorage) {
       this.webConsoleClient.clearMessagesCache();
     }