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

Status: VERIFIED FIXED

(DevTools :: Performance Tools (Profiler/Timeline), defect)

Description

[Paul Rouget [:paul]]

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

Comment 1

[Paul Rouget [:paul]]

I'm planning to use console.time("XXX"); console.timeEnd("XXX");

Comment 2

[Paul Rouget [:paul]]

Attachment: WIP

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.

Comment 3

[Paul Rouget [:paul]]

Attachment: v1

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.

Comment 4

[Paul Rouget [:paul]]

Attachment: v1

Sorry. Wrong patch.

Comment 5

[Paul Rouget [:paul]]

(commit message in the patch is wrong)

Comment 6

[Paul Rouget [:paul]]

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).

Comment 7

[Paul Rouget [:paul]]

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.

Comment 8

[Paul Rouget [:paul]]

Attachment: v2

Tom, Patrick, as soon as you both r+/f+'ed my patch, I'll ask a platform peer to review it as well.

Comment 9

[Tom Tromey :tromey]

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?

Comment 10

[Paul Rouget [:paul]]

(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.

Comment 11

[Tom Tromey :tromey]

> 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.

Comment 12

[Paul Rouget [:paul]]

(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 13

[Patrick Brosset <:pbro>]

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.

Comment 14

[Paul Rouget [:paul]]

Attachment: v3

Comment 15

[Paul Rouget [:paul]]

Attachment: v3

typo.

Comment 16

[Paul Rouget [:paul]]

(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.

Comment 17

[Paul Rouget [:paul]]

Attachment: addendum

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.

Comment 18

[Patrick Brosset <:pbro>]

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.

Comment 19

[Paul Rouget [:paul]]

> ::: 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.

Comment 20

[Paul Rouget [:paul]]

(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 21

[Victor Porof [:vporof][:vp]]

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 :)

Comment 22

[Victor Porof [:vporof][:vp]]

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.

Comment 23

[Paul Rouget [:paul]]

(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.

Comment 24

[Paul Rouget [:paul]]

> @@ +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.

Comment 25

[Paul Rouget [:paul]]

Victor, ignore comment 23, I thought you were talking about sorting.

Comment 26

[Paul Rouget [:paul]]

Attachment: v3 (r=vporof,r=pbrosset)

Andrea, can you please take a look at console.cpp?

Comment 27

[Andrea Marchesini [:baku]]

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 '('

Comment 28

[Paul Rouget [:paul]]

(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.

Comment 29

[Paul Rouget [:paul]]

(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.

Comment 30

[Paul Rouget [:paul]]

Attachment: v3 (r=vporof,r=pbrosset,r=baku)

Rebased. Addressed Andrea's comment.

Comment 31

[Paul Rouget [:paul]]

https://tbpl.mozilla.org/?tree=Try&rev=29d00b9f95fe

Comment 32

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/integration/fx-team/rev/da2f24716a5e

Comment 33

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/da2f24716a5e

Comment 34

[Andrei Vaida [:avaida]]

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.

Comment 35

[David Lawrence [:dkl]]

Sorry for the spam. Moving bugs to Firefox :: Developer Tools: Performance Tools (Profiler/Timeline).

dkl