Bug 658368 - Expand console object with time and timeEnd methods that add a simple timer implementation; r=msucan,sdwilsh sr=gavin

browser/devtools/webconsole/HUDService.jsm

@@ -198,7 +198,9 @@ const LEVELS = {
   dir: SEVERITY_LOG,
   group: SEVERITY_LOG,
   groupCollapsed: SEVERITY_LOG,
-  groupEnd: SEVERITY_LOG
+  groupEnd: SEVERITY_LOG,
+  time: SEVERITY_LOG,
+  timeEnd: SEVERITY_LOG
 };
 
 // The lowest HTTP response code (inclusive) that is considered an error.
@@ -2094,6 +2096,30 @@ HUD_SERVICE.prototype =
         }
         return;
 
+      case "time":
+        if (!args) {
+          return;
+        }
+        if (args.error) {
+          Cu.reportError(this.getStr(args.error));
+          return;
+        }
+        body = this.getFormatStr("timerStarted", [args.name]);
+        clipboardText = body;
+        sourceURL = aMessage.filename;
+        sourceLine = aMessage.lineNumber;
+        break;
+
+      case "timeEnd":
+        if (!args) {
+          return;
+        }
+        body = this.getFormatStr("timeEnd", [args.name, args.duration]);
+        clipboardText = body;
+        sourceURL = aMessage.filename;
+        sourceLine = aMessage.lineNumber;
+        break;
+
       default:
         Cu.reportError("Unknown Console API log level: " + level);
         return;

browser/devtools/webconsole/test/browser/Makefile.in

@@ -149,6 +149,7 @@ _BROWSER_TEST_FILES = \
 	browser_gcli_integrate.js \
 	browser_gcli_require.js \
 	browser_gcli_web.js \
+	browser_webconsole_bug_658368_time_methods.js \
 	head.js \
 	$(NULL)
 
@@ -220,6 +221,7 @@ _BROWSER_TEST_PAGES = \
 	test-bug-678816-content.js \
 	test-file-location.js \
 	browser_gcli_inspect.html \
+	test-bug-658368-time-methods.html \
 	$(NULL)
 
 libs:: $(_BROWSER_TEST_FILES)

browser/devtools/webconsole/test/browser/browser_webconsole_bug_658368_time_methods.js

@@ -0,0 +1,87 @@
+/* vim:set ts=2 sw=2 sts=2 et: */
+/*
+ * Any copyright is dedicated to the Public Domain.
+ * http://creativecommons.org/publicdomain/zero/1.0/
+ */
+
+// Tests that the Console API implements the time() and timeEnd() methods.
+
+function test() {
+  addTab("http://example.com/browser/browser/devtools/webconsole/" +
+         "test/browser/test-bug-658368-time-methods.html");
+  openConsole();
+  browser.addEventListener("load", onLoad, true);
+}
+
+function onLoad(aEvent) {
+  browser.removeEventListener(aEvent.type, onLoad, true);
+
+  let hudId = HUDService.getHudIdByWindow(content);
+  let hud = HUDService.hudReferences[hudId];
+  outputNode = hud.outputNode;
+
+  executeSoon(function() {
+    findLogEntry("aTimer: timer started");
+    findLogEntry("ms");
+
+    // The next test makes sure that timers with the same name but in separate
+    // tabs, do not contain the same value.
+    addTab("data:text/html,<script type='text/javascript'>" +
+           "console.timeEnd('bTimer');</script>");
+    openConsole();
+    browser.addEventListener("load", testTimerIndependenceInTabs, true);
+  });
+}
+
+function testTimerIndependenceInTabs(aEvent) {
+  browser.removeEventListener(aEvent.type, testTimerIndependenceInTabs, true);
+
+  let hudId = HUDService.getHudIdByWindow(content);
+  let hud = HUDService.hudReferences[hudId];
+  outputNode = hud.outputNode;
+
+  executeSoon(function() {
+    testLogEntry(outputNode, "bTimer: timer started", "bTimer was not started",
+                 false, true);
+
+    // The next test makes sure that timers with the same name but in separate
+    // pages, do not contain the same value.
+    browser.addEventListener("load", testTimerIndependenceInSameTab, true);
+    content.location = "data:text/html,<script type='text/javascript'>" +
+           "console.time('bTimer');</script>";
+  });
+}
+
+function testTimerIndependenceInSameTab(aEvent) {
+  browser.removeEventListener(aEvent.type, testTimerIndependenceInSameTab, true);
+
+  let hudId = HUDService.getHudIdByWindow(content);
+  let hud = HUDService.hudReferences[hudId];
+  outputNode = hud.outputNode;
+
+  executeSoon(function() {
+    findLogEntry("bTimer: timer started");
+    hud.jsterm.clearOutput();
+
+    // Now the following console.timeEnd() call shouldn't display anything,
+    // if the timers in different pages are not related.
+    browser.addEventListener("load", testTimerIndependenceInSameTabAgain, true);
+    content.location = "data:text/html,<script type='text/javascript'>" +
+           "console.timeEnd('bTimer');</script>";
+  });
+}
+
+function testTimerIndependenceInSameTabAgain(aEvent) {
+  browser.removeEventListener(aEvent.type, testTimerIndependenceInSameTabAgain, true);
+
+  let hudId = HUDService.getHudIdByWindow(content);
+  let hud = HUDService.hudReferences[hudId];
+  outputNode = hud.outputNode;
+
+  executeSoon(function() {
+    testLogEntry(outputNode, "bTimer: timer started", "bTimer was not started",
+                 false, true);
+
+    finishTest();
+  });
+}

browser/devtools/webconsole/test/browser/test-bug-658368-time-methods.html

@@ -0,0 +1,23 @@
+<!DOCTYPE html>
+<html>
+<!-- Any copyright is dedicated to the Public Domain.
+   http://creativecommons.org/publicdomain/zero/1.0/ -->
+  <head>
+    <title>Test for bug 658368: Expand console object with time and timeEnd
+      methods</title>
+  </head>
+  <body>
+    <h1>Test for bug 658368: Expand console object with time and timeEnd
+      methods</h1>
+
+    <script type="text/javascript">
+      function foo() {
+        console.timeEnd("aTimer");
+      }
+      console.time("aTimer");
+      foo();
+      console.time("bTimer");
+    </script>
+  </body>
+</html>
+

browser/devtools/webconsole/test/browser/test-console-extras.html

@@ -4,8 +4,6 @@
     <script type="text/javascript">
       function test() {
         console.log("start");
-        console.time();
-        console.timeEnd()
         console.exception()
         console.assert()
         console.clear()

browser/locales/en-US/chrome/browser/devtools/webconsole.properties

@@ -172,3 +172,15 @@ stacktrace.anonymousFunction=<anonymous>
 # to console.trace(). The stack trace of JavaScript function calls is displayed.
 # In this minimal message we only show the last call.
 stacktrace.outputMessage=Stack trace from %S, function %S, line %S.
+
+# LOCALIZATION NOTE (timerStarted):
+# This string is used to display the result of the console.time() call.
+# %S=name of timer
+timerStarted=%S: timer started
+
+# LOCALIZATION NOTE (timeEnd):
+# This string is used to display the result of the console.timeEnd() call.
+# %1$S=name of timer, %2$S=number of milliseconds
+timeEnd=%1$S: %2$Sms
+
+maxTimersExceeded=The maximum allowed number of timers in this page was exceeded.

dom/base/ConsoleAPI.js

@@ -24,6 +24,7 @@
  *  Ryan Flint <rflint@mozilla.com>
  *  Rob Campbell <rcampbell@mozilla.com>
  *  Mihai Sucan <mihai.sucan@gmail.com>
+ *  Panos Astithas <past@mozilla.com>
  *
  * Alternatively, the contents of this file may be used under the terms of
  * either the GNU General Public License Version 2 or later (the "GPL"), or
@@ -42,6 +43,8 @@
 let Cu = Components.utils;
 let Ci = Components.interfaces;
 let Cc = Components.classes;
+// The maximum allowed number of concurrent timers per page.
+const MAX_PAGE_TIMERS = 10000;
 
 Cu.import("resource://gre/modules/XPCOMUtils.jsm");
 Cu.import("resource://gre/modules/Services.jsm");
@@ -56,6 +59,9 @@ ConsoleAPI.prototype = {
 
   // nsIDOMGlobalPropertyInitializer
   init: function CA_init(aWindow) {
+    Services.obs.addObserver(this, "xpcom-shutdown", false);
+    Services.obs.addObserver(this, "inner-window-destroyed", false);
+
     let outerID;
     let innerID;
     try {
@@ -103,6 +109,12 @@ ConsoleAPI.prototype = {
       groupEnd: function CA_groupEnd() {
         self.notifyObservers(outerID, innerID, "groupEnd", arguments);
       },
+      time: function CA_time() {
+        self.notifyObservers(outerID, innerID, "time", self.startTimer(innerID, arguments[0]));
+      },
+      timeEnd: function CA_timeEnd() {
+        self.notifyObservers(outerID, innerID, "timeEnd", self.stopTimer(innerID, arguments[0]));
+      },
       __exposedProps__: {
         log: "r",
         info: "r",
@@ -113,7 +125,9 @@ ConsoleAPI.prototype = {
         dir: "r",
         group: "r",
         groupCollapsed: "r",
-        groupEnd: "r"
+        groupEnd: "r",
+        time: "r",
+        timeEnd: "r"
       }
     };
 
@@ -135,6 +149,8 @@ ConsoleAPI.prototype = {
       group: genPropDesc('group'),
       groupCollapsed: genPropDesc('groupCollapsed'),
       groupEnd: genPropDesc('groupEnd'),
+      time: genPropDesc('time'),
+      timeEnd: genPropDesc('timeEnd'),
       __noSuchMethod__: { enumerable: true, configurable: true, writable: true,
                           value: function() {} },
       __mozillaConsole__: { value: true }
@@ -146,6 +162,18 @@ ConsoleAPI.prototype = {
     return contentObj;
   },
 
+  observe: function CA_observe(aSubject, aTopic, aData)
+  {
+    if (aTopic == "xpcom-shutdown") {
+      Services.obs.removeObserver(this, "xpcom-shutdown");
+      Services.obs.removeObserver(this, "inner-window-destroyed");
+    }
+    else if (aTopic == "inner-window-destroyed") {
+      let innerWindowID = aSubject.QueryInterface(Ci.nsISupportsPRUint64).data;
+      delete this.timerRegistry[innerWindowID + ""];
+    }
+  },
+
   /**
    * Notify all observers of any console API call.
    *
@@ -254,6 +282,76 @@ ConsoleAPI.prototype = {
    **/
   beginGroup: function CA_beginGroup() {
     return Array.prototype.join.call(arguments[0], " ");
+  },
+
+  /*
+   * A registry of started timers. It contains a map of pages (defined by their
+   * inner window IDs) to timer maps. Timer maps are key-value pairs of timer
+   * names to timer start times, for all timers defined in that page. Timer
+   * names are prepended with the inner window ID in order to avoid conflicts
+   * with Object.prototype functions.
+   */
+  timerRegistry: {},
+
+  /**
+   * Create a new timer by recording the current time under the specified name.
+   *
+   * @param number aWindowId
+   *        The inner ID of the window.
+   * @param string aName
+   *        The name of the timer.
+   * @return object
+   *        The name property holds the timer name and the started property
+   *        holds the time the timer was started. In case of error, it returns
+   *        an object with the single property "error" that contains the key
+   *        for retrieving the localized error message.
+   **/
+  startTimer: function CA_startTimer(aWindowId, aName) {
+    if (!aName) {
+        return;
+    }
+    let innerID = aWindowId + "";
+    if (!this.timerRegistry[innerID]) {
+        this.timerRegistry[innerID] = {};
+    }
+    let pageTimers = this.timerRegistry[innerID];
+    if (Object.keys(pageTimers).length > MAX_PAGE_TIMERS - 1) {
+        return { error: "maxTimersExceeded" };
+    }
+    let key = aWindowId + "-" + aName.toString();
+    if (!pageTimers[key]) {
+        pageTimers[key] = Date.now();
+    }
+    return { name: aName, started: pageTimers[key] };
+  },
+
+  /**
+   * Stop the timer with the specified name and retrieve the elapsed time.
+   *
+   * @param number aWindowId
+   *        The inner ID of the window.
+   * @param string aName
+   *        The name of the timer.
+   * @return object
+   *        The name property holds the timer name and the duration property
+   *        holds the number of milliseconds since the timer was started.
+   **/
+  stopTimer: function CA_stopTimer(aWindowId, aName) {
+    if (!aName) {
+        return;
+    }
+    let innerID = aWindowId + "";
+    let pageTimers = this.timerRegistry[innerID];
+    if (!pageTimers) {
+        return;
+    }
+    let key = aWindowId + "-" + aName.toString();
+    if (!pageTimers[key]) {
+        return;
+    }
+    let duration = Date.now() - pageTimers[key];
+    delete pageTimers[key];
+    return { name: aName, duration: duration };
   }
 };
 

dom/tests/browser/browser_ConsoleAPITests.js

@@ -124,7 +124,7 @@ function startGroupTest() {
   };
   let button = gWindow.document.getElementById("test-groups");
   ok(button, "found #test-groups button");
-  EventUtils.synthesizeMouse(button, 2, 2, {}, gWindow);
+  EventUtils.synthesizeMouseAtCenter(button, {}, gWindow);
 }
 
 function testConsoleGroup(aMessageObject) {
@@ -137,7 +137,7 @@ function testConsoleGroup(aMessageObject) {
      "expected level received");
 
   is(aMessageObject.functionName, "testGroups", "functionName matches");
-  ok(aMessageObject.lineNumber >= 32 && aMessageObject.lineNumber <= 34,
+  ok(aMessageObject.lineNumber >= 45 && aMessageObject.lineNumber <= 47,
      "lineNumber matches");
   if (aMessageObject.level == "groupCollapsed") {
     ok(aMessageObject.arguments == "a group", "groupCollapsed arguments matches");
@@ -150,9 +150,7 @@ function testConsoleGroup(aMessageObject) {
   }
 
   if (aMessageObject.level == "groupEnd") {
-    // Test finished
-    ConsoleObserver.destroy();
-    finish();
+    startTimeTest();
   }
 }
 
@@ -167,7 +165,7 @@ function startTraceTest() {
 
   let button = gWindow.document.getElementById("test-trace");
   ok(button, "found #test-trace button");
-  EventUtils.synthesizeMouse(button, 2, 2, {}, gWindow);
+  EventUtils.synthesizeMouseAtCenter(button, {}, gWindow);
 }
 
 function startLocationTest() {
@@ -188,7 +186,7 @@ function startLocationTest() {
 
   let button = gWindow.document.getElementById("test-location");
   ok(button, "found #test-location button");
-  EventUtils.synthesizeMouse(button, 2, 2, {}, gWindow);
+  EventUtils.synthesizeMouseAtCenter(button, {}, gWindow);
 }
 
 function expect(level) {
@@ -250,6 +248,114 @@ function consoleAPISanityTest() {
   ok(win.console.group, "console.group is here");
   ok(win.console.groupCollapsed, "console.groupCollapsed is here");
   ok(win.console.groupEnd, "console.groupEnd is here");
+  ok(win.console.time, "console.time is here");
+  ok(win.console.timeEnd, "console.timeEnd is here");
+}
+
+function startTimeTest() {
+  // Reset the observer function to cope with the fabricated test data.
+  ConsoleObserver.observe = function CO_observe(aSubject, aTopic, aData) {
+    try {
+      testConsoleTime(aSubject.wrappedJSObject);
+    } catch (ex) {
+      // XXX Exceptions in this function currently aren't reported, because of
+      // some XPConnect weirdness, so report them manually
+      ok(false, "Exception thrown in CO_observe: " + ex);
+    }
+  };
+  gLevel = "time";
+  gArgs = [
+    {filename: TEST_URI, lineNumber: 23, functionName: "startTimer"},
+  ];
+
+  let button = gWindow.document.getElementById("test-time");
+  ok(button, "found #test-time button");
+  EventUtils.synthesizeMouseAtCenter(button, {}, gWindow);
+}
+
+function testConsoleTime(aMessageObject) {
+  let messageWindow = getWindowByWindowId(aMessageObject.ID);
+  is(messageWindow, gWindow, "found correct window by window ID");
+
+  is(aMessageObject.level, gLevel, "expected level received");
+
+  is(aMessageObject.filename, gArgs[0].filename, "filename matches");
+  is(aMessageObject.lineNumber, gArgs[0].lineNumber, "lineNumber matches");
+  is(aMessageObject.functionName, gArgs[0].functionName, "functionName matches");
+
+  startTimeEndTest();
+}
+
+function startTimeEndTest() {
+  // Reset the observer function to cope with the fabricated test data.
+  ConsoleObserver.observe = function CO_observe(aSubject, aTopic, aData) {
+    try {
+      testConsoleTimeEnd(aSubject.wrappedJSObject);
+    } catch (ex) {
+      // XXX Exceptions in this function currently aren't reported, because of
+      // some XPConnect weirdness, so report them manually
+      ok(false, "Exception thrown in CO_observe: " + ex);
+    }
+  };
+  gLevel = "timeEnd";
+  gArgs = [
+    {filename: TEST_URI, lineNumber: 27, functionName: "stopTimer", arguments: { name: "foo" }},
+  ];
+
+  let button = gWindow.document.getElementById("test-timeEnd");
+  ok(button, "found #test-timeEnd button");
+  EventUtils.synthesizeMouseAtCenter(button, {}, gWindow);
+}
+
+function testConsoleTimeEnd(aMessageObject) {
+  let messageWindow = getWindowByWindowId(aMessageObject.ID);
+  is(messageWindow, gWindow, "found correct window by window ID");
+
+  is(aMessageObject.level, gLevel, "expected level received");
+  ok(aMessageObject.arguments, "we have arguments");
+
+  is(aMessageObject.filename, gArgs[0].filename, "filename matches");
+  is(aMessageObject.lineNumber, gArgs[0].lineNumber, "lineNumber matches");
+  is(aMessageObject.functionName, gArgs[0].functionName, "functionName matches");
+  is(aMessageObject.arguments.length, gArgs[0].arguments.length, "arguments.length matches");
+  is(aMessageObject.arguments.name, gArgs[0].arguments.name, "timer name matches");
+  ok(typeof aMessageObject.arguments.duration == "number", "timer duration is a number");
+  ok(aMessageObject.arguments.duration > 0, "timer duration is positive");
+
+  startEmptyTimerTest();
+}
+
+function startEmptyTimerTest() {
+  // Reset the observer function to cope with the fabricated test data.
+  ConsoleObserver.observe = function CO_observe(aSubject, aTopic, aData) {
+    try {
+      testEmptyTimer(aSubject.wrappedJSObject);
+    } catch (ex) {
+      // XXX Exceptions in this function currently aren't reported, because of
+      // some XPConnect weirdness, so report them manually
+      ok(false, "Exception thrown in CO_observe: " + ex);
+    }
+  };
+
+  let button = gWindow.document.getElementById("test-namelessTimer");
+  ok(button, "found #test-namelessTimer button");
+  EventUtils.synthesizeMouseAtCenter(button, {}, gWindow);
+}
+
+function testEmptyTimer(aMessageObject) {
+  let messageWindow = getWindowByWindowId(aMessageObject.ID);
+  is(messageWindow, gWindow, "found correct window by window ID");
+
+  ok(aMessageObject.level == "time" || aMessageObject.level == "timeEnd",
+     "expected level received");
+  ok(!aMessageObject.arguments, "we don't have arguments");
+
+  is(aMessageObject.functionName, "namelessTimer", "functionName matches");
+  ok(aMessageObject.lineNumber == 31 || aMessageObject.lineNumber == 32,
+     "lineNumber matches");
+  // Test finished
+  ConsoleObserver.destroy();
+  finish();
 }
 
 var ConsoleObserver = {

dom/tests/browser/test-console-api.html

@@ -19,6 +19,19 @@
         console.log(omg, "o", "d");
       }
 
+      function startTimer(timer) {
+        console.time(timer);
+      }
+
+      function stopTimer(timer) {
+        console.timeEnd(timer);
+      }
+
+      function namelessTimer() {
+        console.time();
+        console.timeEnd();
+      }
+
       function test() {
         var str = "Test Message."
         console.foobar(str); // if this throws, we don't execute following funcs
@@ -41,5 +54,8 @@
     <button id="test-trace" onclick="foobar585956a('omg');">Test trace</button>
     <button id="test-location" onclick="foobar646025('omg');">Test location</button>
     <button id="test-groups" onclick="testGroups();">Test groups</button>
+    <button id="test-time" onclick="startTimer('foo');">Test time</button>
+    <button id="test-timeEnd" onclick="stopTimer('foo');">Test timeEnd</button>
+    <button id="test-namelessTimer" onclick="namelessTimer();">Test namelessTimer</button>
   </body>
 </html>

dom/tests/mochitest/general/test_consoleAPI.html

@@ -30,6 +30,8 @@ function doTest() {
     "group": "function",
     "groupCollapsed": "function",
     "groupEnd": "function",
+    "time": "function",
+    "timeEnd": "function",
     "__noSuchMethod__": "function"
   };