Bug 1423517 - Helps tracking JS allocations when running DevTools tests. r=jdescottes draft
authorAlexandre Poirot <poirot.alex@gmail.com>
Wed, 06 Dec 2017 01:36:51 -0800
changeset 723489 91a6d76f3d111115c7ff43d964f8dc389bfaa848
parent 723473 e2bb11b88bd45bdb2e055042e1624b74d414e73c
child 746874 cbffb47f0b2b9c63e67f85d834bb2209052e0f5e
push id96445
push userbmo:poirot.alex@gmail.com
push dateTue, 23 Jan 2018 12:27:59 +0000
reviewersjdescottes
bugs1423517
milestone60.0a1
Bug 1423517 - Helps tracking JS allocations when running DevTools tests. r=jdescottes MozReview-Commit-ID: 7PWgsUyR54Q
devtools/client/framework/test/shared-head.js
devtools/shared/moz.build
devtools/shared/test-helpers/allocation-tracker.js
devtools/shared/test-helpers/moz.build
testing/talos/talos/tests/devtools/addon/content/damp.js
--- a/devtools/client/framework/test/shared-head.js
+++ b/devtools/client/framework/test/shared-head.js
@@ -94,16 +94,33 @@ const ConsoleObserver = {
   }
 };
 
 Services.obs.addObserver(ConsoleObserver, "console-api-log-event");
 registerCleanupFunction(() => {
   Services.obs.removeObserver(ConsoleObserver, "console-api-log-event");
 });
 
+// Print allocation count if DEBUG_DEVTOOLS_ALLOCATIONS is set to "normal",
+// and allocation sites if DEBUG_DEVTOOLS_ALLOCATIONS is set to "verbose".
+const env = Cc["@mozilla.org/process/environment;1"].getService(Ci.nsIEnvironment);
+const DEBUG_ALLOCATIONS = env.get("DEBUG_DEVTOOLS_ALLOCATIONS");
+if (DEBUG_ALLOCATIONS) {
+  const { allocationTracker } = require("devtools/shared/test-helpers/allocation-tracker");
+  let tracker = allocationTracker();
+  registerCleanupFunction(() => {
+    if (DEBUG_ALLOCATIONS == "normal") {
+      tracker.logCount();
+    } else if (DEBUG_ALLOCATIONS == "verbose") {
+      tracker.logAllocationSites();
+    }
+    tracker.stop();
+  });
+}
+
 var waitForTime = DevToolsUtils.waitForTime;
 
 function getFrameScript() {
   let mm = gBrowser.selectedBrowser.messageManager;
   let frameURL = "chrome://devtools/content/shared/frame-script-utils.js";
   mm.loadFrameScript(frameURL, false);
   SimpleTest.registerCleanupFunction(() => {
     mm = null;
--- a/devtools/shared/moz.build
+++ b/devtools/shared/moz.build
@@ -28,16 +28,20 @@ DIRS += [
     'sourcemap',
     'sprintfjs',
     'specs',
     'transport',
     'webconsole',
     'worker',
 ]
 
+# Only ship test helpers in local builds
+if not CONFIG['MOZILLA_OFFICIAL']:
+    DIRS += ['test-helpers']
+
 BROWSER_CHROME_MANIFESTS += ['tests/browser/browser.ini']
 MOCHITEST_CHROME_MANIFESTS += ['tests/mochitest/chrome.ini']
 XPCSHELL_TESTS_MANIFESTS += ['tests/unit/xpcshell.ini']
 
 JAR_MANIFESTS += ['jar.mn']
 
 DevToolsModules(
     'async-storage.js',
new file mode 100644
--- /dev/null
+++ b/devtools/shared/test-helpers/allocation-tracker.js
@@ -0,0 +1,188 @@
+/* this source code form is subject to the terms of the mozilla public
+ * license, v. 2.0. if a copy of the mpl was not distributed with this
+ * file, you can obtain one at http://mozilla.org/mpl/2.0/. */
+
+/*
+ * This file helps tracking Javascript object allocations.
+ * It is only included in local builds as a debugging helper.
+ *
+ * It is typicaly used when running DevTools tests (either mochitests or DAMP).
+ * To use it, you need to set the following environment variable:
+ *   DEBUG_DEVTOOLS_ALLOCATIONS="normal"
+ *     This will only print the number of JS objects created during your test.
+ *   DEBUG_DEVTOOLS_ALLOCATIONS="verbose"
+ *     This will print the allocation sites of all the JS objects created during your
+ *     test. i.e. from which files and lines the objects have been created.
+ * In both cases, look for "DEVTOOLS ALLOCATION" in your terminal to see tracker's
+ * output.
+ *
+ * But you can also import it from your test script if you want to focus on one
+ * particular piece of code:
+ *   const { allocationTracker } =
+ *     require("devtools/shared/test-helpers/allocation-tracker");
+ *   // Calling `allocationTracker` will immediately start recording allocations
+ *   let tracker = allocationTracker();
+ *
+ *   // Do something
+ *
+ *   // If you want to log all the allocation sites, call this method:
+ *   tracker.logAllocationSites();
+ *   // Or, if you want to only print the number of objects being allocated, call this:
+ *   tracker.logCount();
+ *   // Once you are done, stop the tracker as it slow down execution a lot.
+ *   tracker.stop();
+ */
+
+"use strict";
+
+let { Cu } = require("chrome");
+
+// Get a "Debugger" constructor. Can't call `addDebuggerToGlobal`
+// on the frame script global, so call it on jsdebugger one...
+let global = Cu.import("resource://gre/modules/jsdebugger.jsm", {});
+const {addDebuggerToGlobal} = global;
+addDebuggerToGlobal(global);
+let { Debugger } = global;
+
+exports.allocationTracker = function () {
+  dump("DEVTOOLS ALLOCATION: Start logging allocations\n");
+  let dbg = new Debugger();
+
+  // Enable allocation site tracking, to have the stack for each allocation
+  dbg.memory.trackingAllocationSites = true;
+  // Force saving *all* the allocation sites
+  dbg.memory.allocationSamplingProbability = 1.0;
+  // Bumps the default buffer size, which may prevent recording all the test allocations
+  dbg.memory.maxAllocationsLogLength = 5000000;
+
+  // Watch all globals
+  dbg.addAllGlobalsAsDebuggees();
+
+  // Remove this global to ignore all its object/JS
+  dbg.removeDebuggee(Cu.getGlobalForObject({}));
+
+  // addAllGlobalsAsDebuggees won't automatically track new ones,
+  // so ensure tracking all new globals
+  dbg.onNewGlobalObject = function (g) {
+    dbg.addDebuggee(g);
+  };
+
+  return {
+    get overflowed() {
+      return dbg.memory.allocationsLogOverflowed;
+    },
+
+    /**
+     * Print to stdout data about all recorded allocations
+     *
+     * It prints an array of allocations per file, sorted by files allocating the most
+     * objects. And get detail of allocation per line.
+     *
+     *   [{ src: "chrome://devtools/content/framework/toolbox.js",
+     *      count: 210, // Total # of allocs for toolbox.js
+     *      lines: [
+     *       "10: 200", // toolbox.js allocation 200 objects on line 10
+     *       "124: 10
+     *      ]
+     *    },
+     *    { src: "chrome://devtools/content/inspector/inspector.js",
+     *      count: 12,
+     *      lines: [
+     *       "20: 12",
+     *      ]
+     *    }]
+     *
+     * @param first Number
+     *        Retrieve only the top $first script allocation the most
+     *        objects
+     */
+    logAllocationSites({ first = 5 } = {}) {
+      // Fetch all allocation sites from Debugger API
+      let allocations = dbg.memory.drainAllocationsLog();
+
+      // Process Debugger API data to store allocations by file
+      // sources = {
+      //   "chrome://devtools/content/framework/toolbox.js": {
+      //     count: 10, // total # of allocs for toolbox.js
+      //     lines: {
+      //       10: 200, // total # of allocs for toolbox.js line 10
+      //       124: 10, // same, for line 124
+      //       ..
+      //     }
+      //   }
+      // }
+      let sources = {};
+      for (let alloc of allocations) {
+        let { frame } = alloc;
+        let src = "UNKNOWN";
+        let line = -1;
+        try {
+          if (frame) {
+            src = frame.source || "UNKNOWN";
+            line = frame.line || -1;
+          }
+        } catch (e) {
+          // For some frames accessing source throws
+        }
+
+        let item = sources[src];
+        if (!item) {
+          item = sources[src] = { count: 0, lines: {} };
+        }
+        item.count++;
+        if (line != -1) {
+          if (!item.lines[line]) {
+            item.lines[line] = 0;
+          }
+          item.lines[line]++;
+        }
+      }
+
+      let allocationList = Object.entries(sources)
+        // Sort by number of total object
+        .sort(([srcA, itemA], [srcB, itemB]) => itemA.count < itemB.count)
+        // Keep only the first 5 sources, with the most allocations
+        .filter((_, i) => i < first)
+        .map(([src, item]) => {
+          let lines = [];
+          Object.entries(item.lines)
+            .filter(([line, count]) => count > 5)
+            .sort(([lineA, countA], [lineB, countB]) => {
+              if (countA != countB) {
+                return countA < countB;
+              }
+              return lineA < lineB;
+            })
+            .forEach(([line, count]) => {
+              // Compress the data to make it readable on stdout
+              lines.push(line + ": " + count);
+            });
+          return { src, count: item.count, lines };
+        });
+      dump("DEVTOOLS ALLOCATION: Javascript object allocations: " + allocations.length +
+           "\n" + JSON.stringify(allocationList, null, 2) + "\n");
+    },
+
+    logCount() {
+      dump("DEVTOOLS ALLOCATION: Javascript object allocations: " +
+           this.countAllocations() + "\n");
+    },
+
+    countAllocations() {
+      // Fetch all allocation sites from Debugger API
+      let allocations = dbg.memory.drainAllocationsLog();
+      return allocations.length;
+    },
+
+    flushAllocations() {
+      dbg.memory.drainAllocationsLog();
+    },
+
+    stop() {
+      dump("DEVTOOLS ALLOCATION: Stop logging allocations\n");
+      dbg.onNewGlobalObject = undefined;
+      dbg.removeAllDebuggees();
+      dbg = null;
+    }
+  };
+};
new file mode 100644
--- /dev/null
+++ b/devtools/shared/test-helpers/moz.build
@@ -0,0 +1,15 @@
+# -*- Mode: python; indent-tabs-mode: nil; tab-width: 40 -*-
+# vim: set filetype=python:
+# This Source Code Form is subject to the terms of the Mozilla Public
+# License, v. 2.0. If a copy of the MPL was not distributed with this
+# file, You can obtain one at http://mozilla.org/MPL/2.0/.
+
+# This directory is only processed for local build
+# where MOZILLA_OFFICIAL isn't set
+
+DevToolsModules(
+    'allocation-tracker.js',
+)
+
+with Files('**'):
+    BUG_COMPONENT = ('Firefox', 'Developer Tools')
--- a/testing/talos/talos/tests/devtools/addon/content/damp.js
+++ b/testing/talos/talos/tests/devtools/addon/content/damp.js
@@ -1,11 +1,13 @@
+const Ci = Components.interfaces;
 const { Services } = Components.utils.import("resource://gre/modules/Services.jsm", {});
 const { XPCOMUtils } = Cu.import("resource://gre/modules/XPCOMUtils.jsm", {});
 const gMgr = Cc["@mozilla.org/memory-reporter-manager;1"].getService(Ci.nsIMemoryReporterManager);
+const env = Cc["@mozilla.org/process/environment;1"].getService(Ci.nsIEnvironment);
 
 XPCOMUtils.defineLazyGetter(this, "require", function() {
   let { require } =
     Components.utils.import("resource://devtools/shared/Loader.jsm", {});
   return require;
 });
 XPCOMUtils.defineLazyGetter(this, "gDevTools", function() {
   let { gDevTools } = require("devtools/client/framework/devtools");
@@ -24,16 +26,21 @@ XPCOMUtils.defineLazyGetter(this, "Chrom
 });
 
 const webserver = Services.prefs.getCharPref("addon.test.damp.webserver");
 
 const SIMPLE_URL = webserver + "/tests/devtools/addon/content/pages/simple.html";
 const COMPLICATED_URL = webserver + "/tests/tp5n/bild.de/www.bild.de/index.html";
 const CUSTOM_URL = webserver + "/tests/devtools/addon/content/pages/custom/$TOOL.html";
 
+// Record allocation count in new subtests if DEBUG_DEVTOOLS_ALLOCATIONS is set to
+// "normal". Print allocation sites to stdout if DEBUG_DEVTOOLS_ALLOCATIONS is set to
+// "verbose".
+const DEBUG_ALLOCATIONS = env.get("DEBUG_DEVTOOLS_ALLOCATIONS");
+
 function getMostRecentBrowserWindow() {
   return Services.wm.getMostRecentWindow("navigator:browser");
 }
 
 function getActiveTab(window) {
   return window.gBrowser.selectedTab;
 }
 
@@ -226,29 +233,46 @@ Damp.prototype = {
    * @param label String
    *        Test title, displayed everywhere in PerfHerder, DevTools Perf Dashboard, ...
    *
    * @return object
    *         With a `done` method, to be called whenever the test is finished running
    *         and we should record its duration.
    */
   runTest(label) {
+    if (DEBUG_ALLOCATIONS) {
+      if (!this.allocationTracker) {
+        this.allocationTracker = this.startAllocationTracker();
+      }
+      // Flush the current allocations before running the test
+      this.allocationTracker.flushAllocations();
+    }
+
     let startLabel = label + ".start";
     performance.mark(startLabel);
     let start = performance.now();
 
     return {
       done: () => {
         let end = performance.now();
         let duration = end - start;
         performance.measure(label, startLabel);
         this._results.push({
           name: label,
           value: duration
         });
+
+        if (DEBUG_ALLOCATIONS == "normal") {
+          this._results.push({
+            name: label + ".allocations",
+            value: this.allocationTracker.countAllocations()
+          });
+        } else if (DEBUG_ALLOCATIONS == "verbose") {
+          this.allocationTracker.logAllocationSites();
+        }
       }
     };
   },
 
   addTab(url) {
     return new Promise((resolve, reject) => {
       let tab = this._win.gBrowser.selectedTab = this._win.gBrowser.addTab(url);
       let browser = tab.linkedBrowser;
@@ -939,16 +963,20 @@ async _consoleOpenWithCachedMessagesTest
     } else {
       // alert(out);
     }
   },
 
   _onTestComplete: null,
 
   _doneInternal() {
+    if (this.allocationTracker) {
+      this.allocationTracker.stop();
+      this.allocationTracker = null;
+    }
     this._logLine("DAMP_RESULTS_JSON=" + JSON.stringify(this._results));
     this._reportAllResults();
     this._win.gBrowser.selectedTab = this._dampTab;
 
     if (this._onTestComplete) {
       this._onTestComplete(JSON.parse(JSON.stringify(this._results))); // Clone results
     }
   },
@@ -1000,24 +1028,28 @@ async _consoleOpenWithCachedMessagesTest
         }
       }
 
       window.on(EVENTS.PAYLOAD_READY, onPayloadReady);
       window.on(EVENTS.RECEIVED_EVENT_TIMINGS, onTimingsUpdated);
     });
   },
 
+  startAllocationTracker() {
+    const { allocationTracker } = require("devtools/shared/test-helpers/allocation-tracker");
+    return allocationTracker();
+  },
+
   startTest(doneCallback, config) {
     this._onTestComplete = function(results) {
       TalosParentProfiler.pause("DAMP - end");
       doneCallback(results);
     };
     this._config = config;
 
-    const Ci = Components.interfaces;
     var wm = Components.classes["@mozilla.org/appshell/window-mediator;1"].getService(Ci.nsIWindowMediator);
     this._win = wm.getMostRecentWindow("navigator:browser");
     this._dampTab = this._win.gBrowser.selectedTab;
     this._win.gBrowser.selectedBrowser.focus(); // Unfocus the URL bar to avoid caret blink
 
     TalosParentProfiler.resume("DAMP - start");
 
     let tests = {};
@@ -1087,11 +1119,13 @@ async _consoleOpenWithCachedMessagesTest
         sequenceArray.push(tests[config.subtests[i]]);
       }
     }
 
     // Free memory before running the first test, otherwise we may have a GC
     // related to Firefox startup or DAMP setup during the first test.
     garbageCollect().then(() => {
       this._doSequence(sequenceArray, this._doneInternal);
+    }).catch(e => {
+      dump("Exception while running DAMP tests: " + e + "\n" + e.stack + "\n");
     });
   }
 };