Bug 922221 - implement console.timeStamp(label) to create profile timeline markers. r=khuey

docshell/base/nsDocShell.cpp

@@ -2987,6 +2987,20 @@ nsDocShell::PopProfileTimelineMarkers(
     // 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;
 

docshell/test/browser/browser_timelineMarkers-frame-02.js

@@ -90,6 +90,33 @@ let TESTS = [{
     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);

dom/base/Console.cpp

@@ -846,6 +846,19 @@ Console::TimeEnd(JSContext* aCx, const JS::Handle<JS::Value> 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)
 {
@@ -1016,6 +1029,27 @@ public:
   }
 };
 
+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,
@@ -1090,7 +1124,9 @@ Console::Method(JSContext* aCx, MethodName aMethodName,
   }
 
   // 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);
@@ -1109,7 +1145,23 @@ Console::Method(JSContext* aCx, MethodName aMethodName,
         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) {

dom/base/Console.h

@@ -92,6 +92,9 @@ public:
   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);
 
@@ -125,6 +128,7 @@ private:
     MethodGroupEnd,
     MethodTime,
     MethodTimeEnd,
+    MethodTimeStamp,
     MethodAssert,
     MethodCount
   };

dom/bindings/Bindings.conf

@@ -287,7 +287,7 @@ DOMInterfaces = {
 },
 
 'Console': {
-    'implicitJSContext': [ 'trace', 'time', 'timeEnd' ],
+    'implicitJSContext': [ 'trace', 'time', 'timeEnd', 'timeStamp' ],
 },
 
 'ConvolverNode': {

dom/tests/browser/browser_ConsoleAPITests.js

@@ -325,6 +325,7 @@ function consoleAPISanityTest() {
   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");
 }
@@ -416,6 +417,85 @@ function testConsoleTimeEnd(aMessageObject) {
     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();
 }
 

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

@@ -53,6 +53,10 @@
       function nativeCallback() {
         new Promise(function(resolve, reject) { resolve(42); }).then(console.log.bind(console));
       }
+
+      function timeStamp(val) {
+        console.timeStamp(val);
+      }
     </script>
   </head>
   <body>
@@ -65,5 +69,7 @@
     <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>

dom/webidl/Console.webidl

@@ -22,6 +22,7 @@ interface Console {
   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);
@@ -38,8 +39,6 @@ interface Console {
   void timeline();
   [BinaryName="noopMethod"]
   void timelineEnd();
-  [BinaryName="noopMethod"]
-  void timeStamp();
 };
 
 // This is used to propagate console events to the observers.

dom/webidl/ProfileTimelineMarker.webidl

@@ -16,7 +16,7 @@ dictionary ProfileTimelineMarker {
   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;

dom/workers/test/console_worker.js

@@ -51,6 +51,10 @@ onmessage = function(event) {
     console.timeEnd(timer);
   }
 
+  function timeStamp(label) {
+    console.timeStamp(label);
+  }
+
   function testGroups() {
     console.groupCollapsed("a", "group");
     console.group("b", "group");
@@ -59,6 +63,8 @@ onmessage = function(event) {
 
   foobar585956a('omg');
   foobar646025('omg');
+  timeStamp();
+  timeStamp('foo');
   testGroups();
   startTimer('foo');
   setTimeout(function() {

tools/profiler/GeckoProfiler.h

@@ -60,7 +60,8 @@ enum TracingMetadata {
   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)