Bug 1050502 - [timeline] display console.time/timeEnd calls as markers. r=pbrosset,r=vporof,r=baku
authorPaul Rouget <paul@mozilla.com>
Wed, 22 Oct 2014 23:51:00 +0200
changeset 211967 da2f24716a5e
parent 211966 6e500121fb42
child 211968 fa3aec4c2aae
push id27694
push userkwierso@gmail.com
push dateFri, 24 Oct 2014 00:17:24 +0000
treeherdermozilla-central@a97b95030a94 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerspbrosset, vporof, baku
bugs1050502
milestone36.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 1050502 - [timeline] display console.time/timeEnd calls as markers. r=pbrosset,r=vporof,r=baku
browser/devtools/timeline/timeline.js
browser/devtools/timeline/widgets/global.js
browser/devtools/timeline/widgets/waterfall.js
browser/locales/en-US/chrome/browser/devtools/timeline.properties
docshell/base/nsDocShell.cpp
docshell/base/nsDocShell.h
docshell/test/browser/browser_timelineMarkers-02.js
dom/base/Console.cpp
dom/base/moz.build
toolkit/devtools/server/actors/timeline.js
--- a/browser/devtools/timeline/timeline.js
+++ b/browser/devtools/timeline/timeline.js
@@ -123,16 +123,19 @@ let TimelineController = {
   },
 
   /**
    * Stops the recording, updating the UI as needed.
    */
   _stopRecording: function*() {
     clearInterval(this._updateId);
 
+    // Sorting markers is only important when displayed in the waterfall.
+    this._markers = this._markers.sort((a,b) => (a.start > b.start));
+
     TimelineView.handleMarkersUpdate(this._markers);
     TimelineView.handleRecordingEnded();
     yield gFront.stop();
   },
 
   /**
    * Used in tests. Stops the recording, discarding the accumulated markers and
    * updating the UI as needed.
--- a/browser/devtools/timeline/widgets/global.js
+++ b/browser/devtools/timeline/widgets/global.js
@@ -38,14 +38,20 @@ const TIMELINE_BLUEPRINT = {
     stroke: "hsl(104,57%,51%)",
     label: L10N.getStr("timeline.label.reflow")
   },
   "Paint": {
     group: 1,
     fill: "hsl(39,82%,69%)",
     stroke: "hsl(39,82%,49%)",
     label: L10N.getStr("timeline.label.paint")
+  },
+  "ConsoleTime": {
+    group: 3,
+    fill: "hsl(0,0%,80%)",
+    stroke: "hsl(0,0%,60%)",
+    label: L10N.getStr("timeline.label.consoleTime")
   }
 };
 
 // Exported symbols.
 exports.L10N = L10N;
 exports.TIMELINE_BLUEPRINT = TIMELINE_BLUEPRINT;
--- a/browser/devtools/timeline/widgets/waterfall.js
+++ b/browser/devtools/timeline/widgets/waterfall.js
@@ -274,18 +274,30 @@ Waterfall.prototype = {
     let bullet = this._document.createElement("hbox");
     bullet.className = "timeline-marker-bullet";
     bullet.style.backgroundColor = blueprint.fill;
     bullet.style.borderColor = blueprint.stroke;
     bullet.setAttribute("type", marker.name);
     sidebar.appendChild(bullet);
 
     let name = this._document.createElement("label");
+    name.setAttribute("crop", "end");
+    name.setAttribute("flex", "1");
     name.className = "plain timeline-marker-name";
-    name.setAttribute("value", blueprint.label);
+
+    let label;
+    if (marker.detail && marker.detail.causeName) {
+      label = this._l10n.getFormatStr("timeline.markerDetailFormat",
+                                      blueprint.label,
+                                      marker.detail.causeName);
+    } else {
+      label = blueprint.label;
+    }
+    name.setAttribute("value", label);
+    name.setAttribute("tooltiptext", label);
     sidebar.appendChild(name);
 
     container.appendChild(sidebar);
   },
 
   /**
    * Creates the waterfall part of a marker in this view.
    *
--- a/browser/locales/en-US/chrome/browser/devtools/timeline.properties
+++ b/browser/locales/en-US/chrome/browser/devtools/timeline.properties
@@ -34,8 +34,15 @@ timeline.tick=%S ms
 timeline.records=RECORDS
 
 # LOCALIZATION NOTE (timeline.label.*):
 # These strings are displayed in the timeline waterfall, identifying markers.
 timeline.label.styles=Styles
 timeline.label.reflow=Reflow
 timeline.label.paint=Paint
 timeline.label.domevent=DOM Event
+timeline.label.consoleTime=Console
+
+# LOCALIZATION NOTE (timeline.markerDetailFormat):
+# Some timeline markers come with details, like a size, a name, a js function.
+# %1$S is replaced with one of the above label (timeline.label.*) and %2$S
+# with the details. For examples: Paint (200x100), or console.time (FOO)
+timeline.markerDetailFormat=%1$S (%2$S)
--- a/docshell/base/nsDocShell.cpp
+++ b/docshell/base/nsDocShell.cpp
@@ -2873,30 +2873,30 @@ nsDocShell::PopProfileTimelineMarkers(JS
   // If we see an unpaired START, we keep it around for the next call
   // to PopProfileTimelineMarkers.  We store the kept START objects in
   // this array.
   decltype(mProfileTimelineMarkers) keptMarkers;
 
   for (uint32_t i = 0; i < mProfileTimelineMarkers.Length(); ++i) {
     ProfilerMarkerTracing* startPayload = static_cast<ProfilerMarkerTracing*>(
       mProfileTimelineMarkers[i]->mPayload);
-    const char* startMarkerName = mProfileTimelineMarkers[i]->mName;
+    const char* startMarkerName = mProfileTimelineMarkers[i]->mName.get();
 
     bool hasSeenPaintedLayer = false;
 
     if (startPayload->GetMetaData() == TRACING_INTERVAL_START) {
       bool hasSeenEnd = false;
 
       // The assumption is that the devtools timeline flushes markers frequently
       // enough for the amount of markers to always be small enough that the
       // nested for loop isn't going to be a performance problem.
       for (uint32_t j = i + 1; j < mProfileTimelineMarkers.Length(); ++j) {
         ProfilerMarkerTracing* endPayload = static_cast<ProfilerMarkerTracing*>(
           mProfileTimelineMarkers[j]->mPayload);
-        const char* endMarkerName = mProfileTimelineMarkers[j]->mName;
+        const char* endMarkerName = mProfileTimelineMarkers[j]->mName.get();
 
         // Look for Layer markers to stream out paint markers.
         if (strcmp(endMarkerName, "Layer") == 0) {
           hasSeenPaintedLayer = true;
         }
 
         bool isSameMarkerType = strcmp(startMarkerName, endMarkerName) == 0;
         bool isPaint = strcmp(startMarkerName, "Paint") == 0;
--- a/docshell/base/nsDocShell.h
+++ b/docshell/base/nsDocShell.h
@@ -965,17 +965,17 @@ private:
         , mTime(aTime)
       {}
 
       ~InternalProfileTimelineMarker()
       {
         delete mPayload;
       }
 
-      const char* mName;
+      nsCString mName;
       ProfilerMarkerTracing* mPayload;
       DOMHighResTimeStamp mTime;
     };
     nsTArray<InternalProfileTimelineMarker*> mProfileTimelineMarkers;
 #endif
 
     // Get rid of all the timeline markers accumulated so far
     void ClearProfileTimelineMarkers();
--- a/docshell/test/browser/browser_timelineMarkers-02.js
+++ b/docshell/test/browser/browser_timelineMarkers-02.js
@@ -42,16 +42,38 @@ let TESTS = [{
     div.setAttribute("class", "change-color add-class");
   },
   check: function(markers) {
     ok(markers.length > 0, "markers were returned");
     ok(!markers.some(m => m.name == "Reflow"), "markers doesn't include Reflow");
     ok(!markers.some(m => m.name == "Paint"), "markers doesn't include Paint");
     ok(markers.some(m => m.name == "Styles"), "markers includes Restyle");
   }
+}, {
+  desc: "sync console.time/timeEnd",
+  setup: function(div, docShell) {
+    content.console.time("FOOBAR");
+    content.console.timeEnd("FOOBAR");
+    let markers = docShell.popProfileTimelineMarkers();
+    is(markers.length, 1, "Got one marker");
+    is(markers[0].name, "ConsoleTime:FOOBAR", "Got ConsoleTime:FOOBAR marker");
+    content.console.time("FOO");
+    content.setTimeout(() => {
+      content.console.time("BAR");
+      content.setTimeout(() => {
+        content.console.timeEnd("FOO");
+        content.console.timeEnd("BAR");
+      }, 100);
+    }, 100);
+  },
+  check: function(markers) {
+    is(markers.length, 2, "Got 2 markers");
+    is(markers[0].name, "ConsoleTime:FOO", "Got ConsoleTime:FOO marker");
+    is(markers[1].name, "ConsoleTime:BAR", "Got ConsoleTime:BARmarker");
+  }
 }];
 
 let test = Task.async(function*() {
   waitForExplicitFinish();
 
   yield openUrl("data:text/html;charset=utf8," + encodeURIComponent(URL));
 
   let docShell = content.QueryInterface(Ci.nsIInterfaceRequestor)
@@ -67,17 +89,17 @@ let test = Task.async(function*() {
 
     info("Running test: " + desc);
 
     info("Flushing the previous markers if any");
     docShell.popProfileTimelineMarkers();
 
     info("Running the test setup function");
     let onMarkers = waitForMarkers(docShell);
-    setup(div);
+    setup(div, docShell);
     info("Waiting for new markers on the docShell");
     let markers = yield onMarkers;
 
     info("Running the test check function");
     check(markers);
   }
 
   info("Stop recording");
--- a/dom/base/Console.cpp
+++ b/dom/base/Console.cpp
@@ -15,16 +15,17 @@
 #include "nsGlobalWindow.h"
 #include "nsJSUtils.h"
 #include "nsPerformance.h"
 #include "ScriptSettings.h"
 #include "WorkerPrivate.h"
 #include "WorkerRunnable.h"
 #include "xpcprivate.h"
 #include "nsContentUtils.h"
+#include "nsDocShell.h"
 
 #include "nsIConsoleAPIStorage.h"
 #include "nsIDOMWindowUtils.h"
 #include "nsIInterfaceRequestorUtils.h"
 #include "nsILoadContext.h"
 #include "nsIServiceManager.h"
 #include "nsISupportsPrimitives.h"
 #include "nsIWebNavigation.h"
@@ -917,16 +918,39 @@ Console::Method(JSContext* aCx, MethodNa
       MOZ_ASSERT(win);
 
       nsRefPtr<nsPerformance> performance = win->GetPerformance();
       if (!performance) {
         return;
       }
 
       callData->mMonotonicTimer = performance->Now();
+
+      // 'time' and 'timeEnd' are displayed in the devtools timeline if active.
+      // Marked as "ConsoleTime:ARG1".
+      bool isTimelineRecording = false;
+      nsDocShell* docShell = static_cast<nsDocShell*>(mWindow->GetDocShell());
+      if (docShell) {
+        docShell->GetRecordProfileTimelineMarkers(&isTimelineRecording);
+      }
+
+      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)) {
+            nsCString str("ConsoleTime:");
+            AppendUTF16toUTF8(key, str);
+            docShell->AddProfileTimelineMarker(str.get(),
+              aMethodName == MethodTime ? TRACING_INTERVAL_START : TRACING_INTERVAL_END);
+          }
+        }
+      }
+
     } else {
       WorkerPrivate* workerPrivate = GetCurrentThreadWorkerPrivate();
       MOZ_ASSERT(workerPrivate);
 
       TimeDuration duration =
         mozilla::TimeStamp::Now() - workerPrivate->CreationTimeStamp();
 
       callData->mMonotonicTimer = duration.ToMilliseconds();
--- a/dom/base/moz.build
+++ b/dom/base/moz.build
@@ -152,16 +152,17 @@ LOCAL_INCLUDES += [
     '../media',
     '../network',
     '../time',
     '../workers',
     '../xbl',
     '/content/base/src',
     '/content/html/document/src',
     '/content/xul/document/src',
+    '/docshell/base',
     '/dom/geolocation',
     '/dom/storage',
     '/layout/base',
     '/layout/generic',
     '/layout/style',
     '/layout/xul',
     '/widget/shared',
 ]
--- a/toolkit/devtools/server/actors/timeline.js
+++ b/toolkit/devtools/server/actors/timeline.js
@@ -143,32 +143,53 @@ let TimelineActor = exports.TimelineActo
     }
 
     let endTime = this.docShells[0].now();
     let markers = [];
 
     for (let docShell of this.docShells) {
       markers = [...markers, ...docShell.popProfileTimelineMarkers()];
     }
+
     if (markers.length > 0) {
+      this._postProcessMarkers(markers);
       events.emit(this, "markers", markers, endTime);
     }
     if (this._memoryActor) {
       events.emit(this, "memory", endTime, this._memoryActor.measure());
     }
     if (this._framerateActor) {
       events.emit(this, "ticks", endTime, this._framerateActor.getPendingTicks());
     }
 
     this._dataPullTimeout = setTimeout(() => {
       this._pullTimelineData();
     }, DEFAULT_TIMELINE_DATA_PULL_TIMEOUT);
   },
 
   /**
+   * Some markers need post processing.
+   * We will eventually do that platform side: bug 1069661
+   */
+  _postProcessMarkers: function(m) {
+    m.forEach(m => {
+      // A marker named "ConsoleTime:foobar" needs
+      // to be renamed "ConsoleTime".
+      let split = m.name.match(/ConsoleTime:(.*)/);
+      if (split && split.length > 0) {
+        if (!m.detail) {
+          m.detail = {}
+        }
+        m.detail.causeName = split[1];
+        m.name = "ConsoleTime";
+      }
+    });
+  },
+
+  /**
    * Are we recording profile markers currently?
    */
   isRecording: method(function() {
     return this._isRecording;
   }, {
     request: {},
     response: {
       value: RetVal("boolean")