[timeline] it should be possible to feed the timeline from the console API

VERIFIED FIXED in Firefox 36

Status

defect
VERIFIED FIXED
5 years ago
Last year

People

(Reporter: paul, Assigned: paul)

Tracking

Trunk
Firefox 36
x86_64
All
Dependency tree / graph
Bug Flags:
qe-verify +

Firefox Tracking Flags

(firefox36 verified)

Details

Attachments

(1 attachment, 8 obsolete attachments)

Chrome allows adding events (console.timeStamp()). We might want to also be able to record markers.

See https://developer.chrome.com/devtools/docs/console#marking-the-timeline
Component: Developer Tools → Developer Tools: Timeline
I'm planning to use console.time("XXX"); console.timeEnd("XXX");
Assignee: nobody → paul
Depends on: 1071056
Depends on: 1071183
Posted patch WIP (obsolete) — Splinter Review
Apparently, the console methods are executed in asynchronously :(

> console.time("X")
> create sync reflow
> consle.timeEnd("X")

We see the X marker happen after the reflow :/

I can move the code in the sync part of the call.
Posted patch v1 (obsolete) — Splinter Review
Tom, can you take a quick look at this?

I had to change the way the name of the marker was stored. We need our own copy of the string.
Attachment #8493755 - Attachment is obsolete: true
Attachment #8494442 - Flags: feedback?(ttromey)
Posted patch v1 (obsolete) — Splinter Review
Sorry. Wrong patch.
Attachment #8494442 - Attachment is obsolete: true
Attachment #8494442 - Flags: feedback?(ttromey)
Attachment #8494444 - Flags: feedback?(ttromey)
(commit message in the patch is wrong)
I'm not sure I'm doing the right thing here.

Chrome supports 3 different APIs:

> console.time(label); console.timeEnd(label);
> console.timeline(label); console.timelineEnd();]
> console.timeStamp();

The issue with console.timeline is you can't nest markers because timelineEnd() doesn't require a label. There can't be multiple console.timeline markers at the same time.

So we have 3 possible approaches:

1) Implement exactly like Chrome. No nesting possible.
2) Implement exactly like Chrome, and show markers for console.time() too.
3) Require a `label` argument in timelineEnd to support nesting.

I would go for 2).
Supporting console.time/timeEnd will bring us marker nesting, and Gaia developers want that.
Let's support console.timeline/timelineEnd in a follow-up bug in order to be compatible with Chrome.
Posted patch v2 (obsolete) — Splinter Review
Tom, Patrick, as soon as you both r+/f+'ed my patch, I'll ask a platform peer to review it as well.
Attachment #8494444 - Attachment is obsolete: true
Attachment #8494444 - Flags: feedback?(ttromey)
Attachment #8494479 - Flags: review?(pbrosset)
Attachment #8494479 - Flags: feedback?(ttromey)
Comment on attachment 8494479 [details] [diff] [review]
v2

Review of attachment 8494479 [details] [diff] [review]:
-----------------------------------------------------------------

The C++ bits all seem fine to me.

One generic comment I have is whether putting the user's argument into the
timeline marker name is what you want to do.  It seems perhaps cleaner to
put that into the "payload" -- but maybe that is harder since it may require
changing ProfileTimelineMarker.webidl?
Attachment #8494479 - Flags: feedback?(ttromey) → feedback+
(In reply to Tom Tromey :tromey from comment #9)
> Comment on attachment 8494479 [details] [diff] [review]
> v2
> 
> Review of attachment 8494479 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> The C++ bits all seem fine to me.
> 
> One generic comment I have is whether putting the user's argument into the
> timeline marker name is what you want to do.  It seems perhaps cleaner to
> put that into the "payload" -- but maybe that is harder since it may require
> changing ProfileTimelineMarker.webidl?

Yeah, we don't support metadata yet. We will, eventually, but we're not there yet. Supporting console.time is high priority for the B2G team, so we'll start that way.
> Yeah, we don't support metadata yet. We will, eventually, but we're not
> there yet. Supporting console.time is high priority for the B2G team, so
> we'll start that way.

I re-read the code a bit more and I see now that the API isn't really there anyhow.
We'd have to subclass ProfilerMarkerTracing and add new overloads of AddProfileTimelineMarker
as well... harder than I had been thinking.
(In reply to Tom Tromey :tromey from comment #11)
> > Yeah, we don't support metadata yet. We will, eventually, but we're not
> > there yet. Supporting console.time is high priority for the B2G team, so
> > we'll start that way.
> 
> I re-read the code a bit more and I see now that the API isn't really there
> anyhow.
> We'd have to subclass ProfilerMarkerTracing and add new overloads of
> AddProfileTimelineMarker
> as well... harder than I had been thinking.

See bug 1069661.
Comment on attachment 8494479 [details] [diff] [review]
v2

Review of attachment 8494479 [details] [diff] [review]:
-----------------------------------------------------------------

Looks ok from what I can tell, but as you said, this needs a review from a platform peer.

::: docshell/test/browser/browser_timelineMarkers-02.js
@@ +55,5 @@
> +    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(() => {

This happens to work because after calling setup, we then call waitForMarkers which waits 200ms before getting markers.
I think it would be cleaner to make setup async, so that we can yield it.
Attachment #8494479 - Flags: review?(pbrosset) → review+
Posted patch v3 (obsolete) — Splinter Review
Attachment #8494479 - Attachment is obsolete: true
Attachment #8495198 - Flags: review?(vporof)
Attachment #8495198 - Flags: review?(pbrosset)
Posted patch v3 (obsolete) — Splinter Review
typo.
Attachment #8495198 - Attachment is obsolete: true
Attachment #8495198 - Flags: review?(vporof)
Attachment #8495198 - Flags: review?(pbrosset)
Attachment #8495202 - Flags: review?(vporof)
Attachment #8495202 - Flags: review?(pbrosset)
(In reply to Patrick Brosset [:pbrosset] [:patrick] from comment #13)
> ::: docshell/test/browser/browser_timelineMarkers-02.js
> @@ +55,5 @@
> > +    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(() => {
> 
> This happens to work because after calling setup, we then call
> waitForMarkers which waits 200ms before getting markers.
> I think it would be cleaner to make setup async, so that we can yield it.

Not sure to understand. I want, in this test, to test a sync and an async call.
Posted patch addendum (obsolete) — Splinter Review
Some UI tweaks.

console.time ("XXX") is too large for the sidebar. Adding overflow-x:hidden and renaming console.time to console.

Also, markers are ordered by `.end`, not by `.start`, so we need to sort the markers before building the waterfall.
Attachment #8495234 - Flags: review?(vporof)
Comment on attachment 8495202 [details] [diff] [review]
v3

Review of attachment 8495202 [details] [diff] [review]:
-----------------------------------------------------------------

::: docshell/test/browser/browser_timelineMarkers-02.js
@@ +51,5 @@
> +  desc: "sync console.time/timeEnd",
> +  setup: function(div, docShell) {
> +    content.console.time("FOOBAR");
> +    content.console.timeEnd("FOOBAR");
> +    let markers = docShell.popProfileTimelineMarkers();

So, disregard my earlier comment about this test, I didn't read it properly and overlooked the fact that you were calling popProfileTimelineMarkers() yourself here. I think it would look clearer to people (like me:)) if it was split into two test cases, one sync, one async. This way you wouldn't have to call pop yourself and would check the sync markers in the check function.
But this is minor.

::: toolkit/devtools/server/actors/timeline.js
@@ +133,5 @@
>  
>    /**
> +   * Some markers need post processing.
> +   */
> +  _postProcessMarkers: function(m) {

I guess this is temporary until we support marker payloads, right? If so, can you please add a comment here saying so.
Attachment #8495202 - Flags: review?(pbrosset) → review+
> ::: toolkit/devtools/server/actors/timeline.js
> @@ +133,5 @@
> >  
> >    /**
> > +   * Some markers need post processing.
> > +   */
> > +  _postProcessMarkers: function(m) {
> 
> I guess this is temporary until we support marker payloads, right? If so,
> can you please add a comment here saying so.

Right. I will.
(In reply to Paul Rouget [:paul] (slow to respond. Ping me on IRC) from comment #17)
> Also, markers are ordered by `.end`, not by `.start`, so we need to sort the
> markers before building the waterfall.

markers *can be* ordered by `.end` (for async end/start).
Comment on attachment 8495202 [details] [diff] [review]
v3

Review of attachment 8495202 [details] [diff] [review]:
-----------------------------------------------------------------

::: browser/devtools/timeline/widgets/global.js
@@ +43,5 @@
>      fill: "hsl(39,82%,69%)",
>      stroke: "hsl(39,82%,49%)",
>      label: L10N.getStr("timeline.label.paint")
> +  },
> +  "ConsoleTime": {

This band is always going to be shown, right? Vertical estate is expensive, even more after bug 1069421, so it might be a good idea to hide this (otherwise empty space) until there's actual markers available.

::: toolkit/devtools/server/actors/timeline.js
@@ +134,5 @@
>    /**
> +   * Some markers need post processing.
> +   */
> +  _postProcessMarkers: function(m) {
> +    m.forEach(m => {

Can this not be done on the platform side? Iterating over the markers after we receive them could consume valuable CPU time (especially if the amount of markers we retrieved in those 200ms is huge). It's something we actively tried to avoid in bug 1070089, and this just makes those efforts wasted :)
Attachment #8495202 - Flags: review?(vporof) → review+
Comment on attachment 8495234 [details] [diff] [review]
addendum

Review of attachment 8495234 [details] [diff] [review]:
-----------------------------------------------------------------

::: browser/devtools/timeline/timeline.js
@@ +89,5 @@
>     */
>    getMarkers: function() {
>      return this._markers;
>    },
>  

Nit: extra newline here.

@@ +94,5 @@
> +
> +  /**
> +   * Make sure markers are propertly sorted.
> +   */
> +  sortMarkers: function() {

Why is this a public method? Why is this a method, even? Can't this just be inlined?

@@ +155,5 @@
>     *        function was invoked.
>     */
>    _onMarkers: function(markers) {
>      Array.prototype.push.apply(this._markers, markers);
> +    this._markers.sort((a,b) => (a.start > b.start));

Why sort *while* recording? You only have to do it once, after the fact.

::: browser/themes/shared/devtools/timeline.inc.css
@@ +98,5 @@
>  
>  .timeline-header-sidebar,
>  .timeline-marker-sidebar {
>    -moz-border-end: 1px solid;
> +  overflow-x: hidden;

You probably want to add crop=end attributes to labels as well.
Attachment #8495234 - Flags: review?(vporof) → review+
(In reply to Victor Porof [:vporof][:vp] from comment #21)
> Comment on attachment 8495202 [details] [diff] [review]
> v3
> 
> Review of attachment 8495202 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: browser/devtools/timeline/widgets/global.js
> @@ +43,5 @@
> >      fill: "hsl(39,82%,69%)",
> >      stroke: "hsl(39,82%,49%)",
> >      label: L10N.getStr("timeline.label.paint")
> > +  },
> > +  "ConsoleTime": {
> 
> This band is always going to be shown, right? Vertical estate is expensive,
> even more after bug 1069421, so it might be a good idea to hide this
> (otherwise empty space) until there's actual markers available.

Let's for that in a follow-up bug.

> ::: toolkit/devtools/server/actors/timeline.js
> @@ +134,5 @@
> >    /**
> > +   * Some markers need post processing.
> > +   */
> > +  _postProcessMarkers: function(m) {
> > +    m.forEach(m => {
> 
> Can this not be done on the platform side? Iterating over the markers after
> we receive them could consume valuable CPU time (especially if the amount of
> markers we retrieved in those 200ms is huge). It's something we actively
> tried to avoid in bug 1070089, and this just makes those efforts wasted :)

No. It's impossible to do that platform side. We send markers when they end, not when they start, so popMarkers might have been called before any sorting might be possible.

But! Sorting happen only once, when recording is done. So even if it takes more than 100ms to sort all the markers, I think it's alright.
> @@ +155,5 @@
> >     *        function was invoked.
> >     */
> >    _onMarkers: function(markers) {
> >      Array.prototype.push.apply(this._markers, markers);
> > +    this._markers.sort((a,b) => (a.start > b.start));

Meh, I thought I removed that.
Victor, ignore comment 23, I thought you were talking about sorting.
Posted patch v3 (r=vporof,r=pbrosset) (obsolete) — Splinter Review
Andrea, can you please take a look at console.cpp?
Attachment #8495202 - Attachment is obsolete: true
Attachment #8495234 - Attachment is obsolete: true
Attachment #8495799 - Flags: review?(amarchesini)
Comment on attachment 8495799 [details] [diff] [review]
v3 (r=vporof,r=pbrosset)

Review of attachment 8495799 [details] [diff] [review]:
-----------------------------------------------------------------

Looks ok. I don't see any mochitest for this new feature. Would be nice to have them before land it.

::: dom/base/Console.cpp
@@ +938,5 @@
> +        JS::Rooted<JSString*> jsString(aCx, JS::ToString(aCx, value));
> +        if (jsString) {
> +          nsAutoJSString key;
> +          if (key.init(aCx, jsString)) {
> +            nsCString str ("ConsoleTime:");

extra space between str and '('
Attachment #8495799 - Flags: review?(amarchesini) → review+
(In reply to Andrea Marchesini (:baku) from comment #27)
> Comment on attachment 8495799 [details] [diff] [review]
> v3 (r=vporof,r=pbrosset)
> 
> Review of attachment 8495799 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Looks ok. I don't see any mochitest for this new feature. Would be nice to
> have them before land it.

Aren't the changes in docshell/test/browser/browser_timelineMarkers-02.js enough?

> ::: dom/base/Console.cpp
> @@ +938,5 @@
> > +        JS::Rooted<JSString*> jsString(aCx, JS::ToString(aCx, value));
> > +        if (jsString) {
> > +          nsAutoJSString key;
> > +          if (key.init(aCx, jsString)) {
> > +            nsCString str ("ConsoleTime:");
> 
> extra space between str and '('

ok.
(In reply to Paul Rouget [:paul] (slow to respond. Ping me on IRC) from comment #28)
> (In reply to Andrea Marchesini (:baku) from comment #27)
> > Comment on attachment 8495799 [details] [diff] [review]
> > v3 (r=vporof,r=pbrosset)
> > 
> > Review of attachment 8495799 [details] [diff] [review]:
> > -----------------------------------------------------------------
> > 
> > Looks ok. I don't see any mochitest for this new feature. Would be nice to
> > have them before land it.
> 
> Aren't the changes in docshell/test/browser/browser_timelineMarkers-02.js
> enough?

Checked with Andrea. He's ok with this.
Rebased. Addressed Andrea's comment.
Attachment #8495799 - Attachment is obsolete: true
Attachment #8510077 - Flags: review+
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/da2f24716a5e
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Whiteboard: [fixed-in-fx-team]
Target Milestone: --- → Firefox 36
Flags: qe-verify+
QA Contact: andrei.vaida
Verified fixed on Nightly 36.0a1 (2014-11-10) using several timers with Windows 7 64-bit, Ubuntu 14.04 LTS 32-bit and Mac OS X 10.9.5.
Status: RESOLVED → VERIFIED
Sorry for the spam. Moving bugs to Firefox :: Developer Tools: Performance Tools (Profiler/Timeline).

dkl
Component: Developer Tools: Timeline → Developer Tools: Performance Tools (Profiler/Timeline)
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.