Bug 922221 - implement console.timeStamp(label) to create profile timeline markers. r=khuey
authorJordan Santell <jsantell@gmail.com>
Wed, 29 Apr 2015 12:48:57 -0700
changeset 274552 641fcb51bd9a8bcb28ce4016b9c6ab4839c62087
parent 274551 77b43decfd15ab40a27e71612e2165fed4446d49
child 274557 30a4ba533b1c0d6debe4d84f79c9e9a868efd052
child 274573 adbc210cb42be58e892f462901fd701d1c90a6b0
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)
reviewerskhuey
bugs922221
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 922221 - implement console.timeStamp(label) to create profile timeline markers. r=khuey
docshell/base/nsDocShell.cpp
docshell/test/browser/browser_timelineMarkers-frame-02.js
dom/base/Console.cpp
dom/base/Console.h
dom/bindings/Bindings.conf
dom/tests/browser/browser_ConsoleAPITests.js
dom/tests/browser/test-console-api.html
dom/webidl/Console.webidl
dom/webidl/ProfileTimelineMarker.webidl
dom/workers/test/console_worker.js
tools/profiler/GeckoProfiler.h
--- a/docshell/base/nsDocShell.cpp
+++ b/docshell/base/nsDocShell.cpp
@@ -2982,16 +2982,30 @@ nsDocShell::PopProfileTimelineMarkers(
 
     bool hasSeenPaintedLayer = false;
     bool isPaint = strcmp(startMarkerName, "Paint") == 0;
 
     // If we are processing a Paint marker, we append information from
     // all the embedded Layer markers to this array.
     dom::Sequence<dom::ProfileTimelineLayerRect> layerRectangles;
 
+    // If this is a TRACING_TIMESTAMP marker, there's no corresponding "end"
+    // marker, as it's a single unit of time, not a duration, create the final
+    // marker here.
+    if (startPayload->GetMetaData() == TRACING_TIMESTAMP) {
+      mozilla::dom::ProfileTimelineMarker* marker =
+        profileTimelineMarkers.AppendElement();
+
+      marker->mName = NS_ConvertUTF8toUTF16(startPayload->GetName());
+      marker->mStart = startPayload->GetTime();
+      marker->mEnd = startPayload->GetTime();
+      startPayload->AddDetails(*marker);
+      continue;
+    }
+
     if (startPayload->GetMetaData() == TRACING_INTERVAL_START) {
       bool hasSeenEnd = false;
 
       // DOM events can be nested, so we must take care when searching
       // for the matching end.  It doesn't hurt to apply this logic to
       // all event types.
       uint32_t markerDepth = 0;
 
--- a/docshell/test/browser/browser_timelineMarkers-frame-02.js
+++ b/docshell/test/browser/browser_timelineMarkers-frame-02.js
@@ -85,11 +85,38 @@ let TESTS = [{
   },
   check: function(markers) {
     is(markers.length, 2, "Got 2 markers");
     is(markers[0].name, "ConsoleTime", "Got first ConsoleTime marker");
     is(markers[0].causeName, "FOO", "Got ConsoleTime FOO detail");
     is(markers[1].name, "ConsoleTime", "Got second ConsoleTime marker");
     is(markers[1].causeName, "BAR", "Got ConsoleTime BAR detail");
   }
+}, {
+  desc: "Timestamps created by console.timeStamp()",
+  searchFor: "Timestamp",
+  setup: function(docshell) {
+    content.console.timeStamp("rock");
+    let markers = docShell.popProfileTimelineMarkers();
+    is(markers.length, 1, "Got one marker");
+    is(markers[0].name, "TimeStamp", "Got Timestamp marker");
+    is(markers[0].causeName, "rock", "Got Timestamp label value");
+    content.console.timeStamp("paper");
+    content.console.timeStamp("scissors");
+    content.console.timeStamp();
+    content.console.timeStamp(undefined);
+  },
+  check: function (markers) {
+    is(markers.length, 4, "Got 4 markers");
+    is(markers[0].name, "TimeStamp", "Got Timestamp marker");
+    is(markers[0].causeName, "paper", "Got Timestamp label value");
+    is(markers[1].name, "TimeStamp", "Got Timestamp marker");
+    is(markers[1].causeName, "scissors", "Got Timestamp label value");
+    is(markers[2].name, "TimeStamp", "Got empty Timestamp marker when no argument given");
+    is(markers[2].causeName, void 0, "Got empty Timestamp label value");
+    is(markers[3].name, "TimeStamp", "Got empty Timestamp marker when argument is undefined");
+    is(markers[3].causeName, void 0, "Got empty Timestamp label value");
+    markers.forEach(m => is(m.end, m.start,
+      "All Timestamp markers should have identical start/end times"));
+  }
 }];
 
 timelineContentTest(TESTS);
--- a/dom/base/Console.cpp
+++ b/dom/base/Console.cpp
@@ -842,16 +842,29 @@ Console::TimeEnd(JSContext* aCx, const J
   if (!aTime.isUndefined()) {
     data.AppendElement(aTime);
   }
 
   Method(aCx, MethodTimeEnd, NS_LITERAL_STRING("timeEnd"), data);
 }
 
 void
+Console::TimeStamp(JSContext* aCx, const JS::Handle<JS::Value> aData)
+{
+  Sequence<JS::Value> data;
+  SequenceRooter<JS::Value> rooter(aCx, &data);
+
+  if (aData.isString()) {
+    data.AppendElement(aData);
+  }
+
+  Method(aCx, MethodTimeStamp, NS_LITERAL_STRING("timeStamp"), data);
+}
+
+void
 Console::Profile(JSContext* aCx, const Sequence<JS::Value>& aData)
 {
   ProfileMethod(aCx, NS_LITERAL_STRING("profile"), aData);
 }
 
 void
 Console::ProfileEnd(JSContext* aCx, const Sequence<JS::Value>& aData)
 {
@@ -1011,16 +1024,37 @@ public:
     if (GetMetaData() == TRACING_INTERVAL_START) {
       aMarker.mCauseName.Construct(GetCause());
     } else {
       aMarker.mEndStack = GetStack();
     }
   }
 };
 
+class TimestampTimelineMarker : public TimelineMarker
+{
+public:
+  TimestampTimelineMarker(nsDocShell* aDocShell,
+                          TracingMetadata aMetaData,
+                          const nsAString& aCause)
+    : TimelineMarker(aDocShell, "TimeStamp", aMetaData, aCause)
+  {
+    CaptureStack();
+    MOZ_ASSERT(aMetaData == TRACING_TIMESTAMP);
+  }
+
+  virtual void AddDetails(mozilla::dom::ProfileTimelineMarker& aMarker) override
+  {
+    if (!GetCause().IsEmpty()) {
+      aMarker.mCauseName.Construct(GetCause());
+    }
+    aMarker.mEndStack = GetStack();
+  }
+};
+
 // Queue a call to a console method. See the CALL_DELAY constant.
 void
 Console::Method(JSContext* aCx, MethodName aMethodName,
                 const nsAString& aMethodString,
                 const Sequence<JS::Value>& aData)
 {
   nsRefPtr<ConsoleCallData> callData(new ConsoleCallData());
 
@@ -1085,17 +1119,19 @@ Console::Method(JSContext* aCx, MethodNa
     callData->mReifiedStack.emplace();
     nsresult rv = ReifyStack(stack, *callData->mReifiedStack);
     if (NS_WARN_IF(NS_FAILED(rv))) {
       return;
     }
   }
 
   // Monotonic timer for 'time' and 'timeEnd'
-  if ((aMethodName == MethodTime || aMethodName == MethodTimeEnd)) {
+  if (aMethodName == MethodTime ||
+      aMethodName == MethodTimeEnd ||
+      aMethodName == MethodTimeStamp) {
     if (mWindow) {
       nsGlobalWindow *win = static_cast<nsGlobalWindow*>(mWindow.get());
       MOZ_ASSERT(win);
 
       nsRefPtr<nsPerformance> performance = win->GetPerformance();
       if (!performance) {
         return;
       }
@@ -1104,17 +1140,33 @@ Console::Method(JSContext* aCx, MethodNa
 
       // 'time' and 'timeEnd' are displayed in the devtools timeline if active.
       bool isTimelineRecording = false;
       nsDocShell* docShell = static_cast<nsDocShell*>(mWindow->GetDocShell());
       if (docShell) {
         docShell->GetRecordProfileTimelineMarkers(&isTimelineRecording);
       }
 
-      if (isTimelineRecording && aData.Length() == 1) {
+      // 'timeStamp' recordings do not need an argument; use empty string
+      // if no arguments passed in
+      if (isTimelineRecording && aMethodName == MethodTimeStamp) {
+        JS::Rooted<JS::Value> value(aCx, aData.Length() == 0 ?
+                                    JS_GetEmptyStringValue(aCx) : aData[0]);
+        JS::Rooted<JSString*> jsString(aCx, JS::ToString(aCx, value));
+        nsAutoJSString key;
+        if (jsString) {
+          key.init(aCx, jsString);
+        }
+
+        mozilla::UniquePtr<TimelineMarker> marker =
+          MakeUnique<TimestampTimelineMarker>(docShell, TRACING_TIMESTAMP, key);
+        docShell->AddProfileTimelineMarker(Move(marker));
+      }
+      // For `console.time(foo)` and `console.timeEnd(foo)`
+      else if (isTimelineRecording && aData.Length() == 1) {
         JS::Rooted<JS::Value> value(aCx, aData[0]);
         JS::Rooted<JSString*> jsString(aCx, JS::ToString(aCx, value));
         if (jsString) {
           nsAutoJSString key;
           if (key.init(aCx, jsString)) {
             mozilla::UniquePtr<TimelineMarker> marker =
               MakeUnique<ConsoleTimelineMarker>(docShell,
                                                 aMethodName == MethodTime ? TRACING_INTERVAL_START : TRACING_INTERVAL_END,
--- a/dom/base/Console.h
+++ b/dom/base/Console.h
@@ -88,16 +88,19 @@ public:
 
   void
   Time(JSContext* aCx, const JS::Handle<JS::Value> aTime);
 
   void
   TimeEnd(JSContext* aCx, const JS::Handle<JS::Value> aTime);
 
   void
+  TimeStamp(JSContext* aCx, const JS::Handle<JS::Value> aData);
+
+  void
   Profile(JSContext* aCx, const Sequence<JS::Value>& aData);
 
   void
   ProfileEnd(JSContext* aCx, const Sequence<JS::Value>& aData);
 
   void
   Assert(JSContext* aCx, bool aCondition, const Sequence<JS::Value>& aData);
 
@@ -120,16 +123,17 @@ private:
     MethodTrace,
     MethodDir,
     MethodDirxml,
     MethodGroup,
     MethodGroupCollapsed,
     MethodGroupEnd,
     MethodTime,
     MethodTimeEnd,
+    MethodTimeStamp,
     MethodAssert,
     MethodCount
   };
 
   void
   Method(JSContext* aCx, MethodName aName, const nsAString& aString,
          const Sequence<JS::Value>& aData);
 
--- a/dom/bindings/Bindings.conf
+++ b/dom/bindings/Bindings.conf
@@ -282,17 +282,17 @@ DOMInterfaces = {
 },
 
 'Clients': {
     'nativeType': 'mozilla::dom::workers::ServiceWorkerClients',
     'headerFile': 'mozilla/dom/workers/bindings/ServiceWorkerClients.h',
 },
 
 'Console': {
-    'implicitJSContext': [ 'trace', 'time', 'timeEnd' ],
+    'implicitJSContext': [ 'trace', 'time', 'timeEnd', 'timeStamp' ],
 },
 
 'ConvolverNode': {
     'implicitJSContext': [ 'buffer' ],
 },
 
 'Coordinates': {
     'headerFile': 'nsGeoPosition.h'
--- a/dom/tests/browser/browser_ConsoleAPITests.js
+++ b/dom/tests/browser/browser_ConsoleAPITests.js
@@ -320,16 +320,17 @@ function consoleAPISanityTest() {
   ok(win.console.exception, "console.exception is here");
   ok(win.console.trace, "console.trace is here");
   ok(win.console.dir, "console.dir is here");
   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");
+  ok(win.console.timeStamp, "console.timeStamp is here");
   ok(win.console.assert, "console.assert is here");
   ok(win.console.count, "console.count is here");
 }
 
 function startTimeTest() {
   // Reset the observer function to cope with the fabricated test data.
   ConsoleObserver.observe = function CO_observe(aSubject, aTopic, aData) {
     try {
@@ -411,16 +412,95 @@ function testConsoleTimeEnd(aMessageObje
   is(typeof aMessageObject.timer.duration, "number", "timer duration is a number");
   info("timer duration: " + aMessageObject.timer.duration);
   ok(aMessageObject.timer.duration >= 0, "timer duration is positive");
 
   gArgs[0].arguments.forEach(function (a, i) {
     is(aMessageObject.arguments[i], a, "correct arg " + i);
   });
 
+  startTimeStampTest();
+}
+
+function startTimeStampTest() {
+  // Reset the observer function to cope with the fabricated test data.
+  ConsoleObserver.observe = function CO_observe(aSubject, aTopic, aData) {
+    try {
+      testConsoleTimeStamp(aSubject.wrappedJSObject);
+    } catch (ex) {
+      // XXX Bug 906593 - 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 = "timeStamp";
+  gArgs = [
+    {filename: TEST_URI, lineNumber: 58, functionName: "timeStamp",
+     arguments: ["!!!"]
+    }
+  ];
+
+  let button = gWindow.document.getElementById("test-timeStamp");
+  ok(button, "found #test-timeStamp button");
+  EventUtils.synthesizeMouseAtCenter(button, {}, gWindow);
+}
+
+function testConsoleTimeStamp(aMessageObject) {
+  let messageWindow = Services.wm.getOuterWindowWithId(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");
+  ok(aMessageObject.timeStamp > 0, "timeStamp is a positive value");
+
+  gArgs[0].arguments.forEach(function (a, i) {
+    is(aMessageObject.arguments[i], a, "correct arg " + i);
+  });
+
+  startEmptyTimeStampTest();
+}
+
+function startEmptyTimeStampTest () {
+  // Reset the observer function to cope with the fabricated test data.
+  ConsoleObserver.observe = function CO_observe(aSubject, aTopic, aData) {
+    try {
+      testEmptyConsoleTimeStamp(aSubject.wrappedJSObject);
+    } catch (ex) {
+      // XXX Bug 906593 - 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 = "timeStamp";
+  gArgs = [
+    {filename: TEST_URI, lineNumber: 58, functionName: "timeStamp",
+     arguments: []
+    }
+  ];
+
+  let button = gWindow.document.getElementById("test-emptyTimeStamp");
+  ok(button, "found #test-emptyTimeStamp button");
+  EventUtils.synthesizeMouseAtCenter(button, {}, gWindow);
+}
+
+function testEmptyConsoleTimeStamp(aMessageObject) {
+  let messageWindow = Services.wm.getOuterWindowWithId(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");
+  ok(aMessageObject.timeStamp > 0, "timeStamp is a positive value");
+  is(aMessageObject.arguments.length, 0, "we don't have arguments");
+
   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);
--- a/dom/tests/browser/test-console-api.html
+++ b/dom/tests/browser/test-console-api.html
@@ -48,22 +48,28 @@
         console.groupCollapsed("a", "group");
         console.group("b", "group");
         console.groupEnd("b", "group");
       }
 
       function nativeCallback() {
         new Promise(function(resolve, reject) { resolve(42); }).then(console.log.bind(console));
       }
+
+      function timeStamp(val) {
+        console.timeStamp(val);
+      }
     </script>
   </head>
   <body>
     <h1>Console API Test Page</h1>
     <button onclick="test();">Log stuff</button>
     <button id="test-trace" onclick="foobar585956a('omg');">Test trace</button>
     <button id="test-location" onclick="foobar646025('omg');">Test location</button>
     <button id="test-nativeCallback" onclick="nativeCallback();">Test nativeCallback</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>
+    <button id="test-timeStamp" onclick="timeStamp('!!!')">Test timeStamp</button>
+    <button id="test-emptyTimeStamp" onclick="timeStamp();">Test emptyTimeStamp</button>
   </body>
 </html>
--- a/dom/webidl/Console.webidl
+++ b/dom/webidl/Console.webidl
@@ -17,34 +17,33 @@ interface Console {
   void trace();
   void dir(any... data);
   void dirxml(any... data);
   void group(any... data);
   void groupCollapsed(any... data);
   void groupEnd(any... data);
   void time(optional any time);
   void timeEnd(optional any time);
+  void timeStamp(optional any data);
 
   void profile(any... data);
   void profileEnd(any... data);
 
   void assert(boolean condition, any... data);
   void count(any... data);
 
   // No-op methods for compatibility with other browsers.
   [BinaryName="noopMethod"]
   void clear();
   [BinaryName="noopMethod"]
   void markTimeline();
   [BinaryName="noopMethod"]
   void timeline();
   [BinaryName="noopMethod"]
   void timelineEnd();
-  [BinaryName="noopMethod"]
-  void timeStamp();
 };
 
 // This is used to propagate console events to the observers.
 dictionary ConsoleEvent {
   (unsigned long long or DOMString) ID;
   (unsigned long long or DOMString) innerID;
   DOMString level = "";
   DOMString filename = "";
--- a/dom/webidl/ProfileTimelineMarker.webidl
+++ b/dom/webidl/ProfileTimelineMarker.webidl
@@ -11,17 +11,17 @@ dictionary ProfileTimelineLayerRect {
   long height = 0;
 };
 
 dictionary ProfileTimelineMarker {
   DOMString name = "";
   DOMHighResTimeStamp start = 0;
   DOMHighResTimeStamp end = 0;
   object? stack = null;
-  /* For ConsoleTime and Javascript markers.  */
+  /* For ConsoleTime, Timestamp and Javascript markers.  */
   DOMString causeName;
   /* For ConsoleTime markers.  */
   object? endStack = null;
   /* For DOMEvent markers.  */
   DOMString type;
   unsigned short eventPhase;
   /* For Paint markers.  */
   sequence<ProfileTimelineLayerRect> rectangles;
--- a/dom/workers/test/console_worker.js
+++ b/dom/workers/test/console_worker.js
@@ -46,24 +46,30 @@ onmessage = function(event) {
   function startTimer(timer) {
     console.time(timer);
   }
 
   function stopTimer(timer) {
     console.timeEnd(timer);
   }
 
+  function timeStamp(label) {
+    console.timeStamp(label);
+  }
+
   function testGroups() {
     console.groupCollapsed("a", "group");
     console.group("b", "group");
     console.groupEnd("b", "group");
   }
 
   foobar585956a('omg');
   foobar646025('omg');
+  timeStamp();
+  timeStamp('foo');
   testGroups();
   startTimer('foo');
   setTimeout(function() {
     stopTimer('foo');
     nextSteps(event);
   }, 10);
 }
 
--- a/tools/profiler/GeckoProfiler.h
+++ b/tools/profiler/GeckoProfiler.h
@@ -55,17 +55,18 @@ namespace mozilla {
 class TimeStamp;
 }
 
 enum TracingMetadata {
   TRACING_DEFAULT,
   TRACING_INTERVAL_START,
   TRACING_INTERVAL_END,
   TRACING_EVENT,
-  TRACING_EVENT_BACKTRACE
+  TRACING_EVENT_BACKTRACE,
+  TRACING_TIMESTAMP
 };
 
 #if !defined(MOZ_ENABLE_PROFILER_SPS) || defined(MOZILLA_XPCOMRT_API)
 
 #include <stdint.h>
 #include <stdarg.h>
 
 // Insert a RAII in this scope to active a pseudo label. Any samples collected