If you think a bug might affect users in the 57 release, please set the correct tracking and status flags for Release Management.

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

VERIFIED FIXED in Firefox 36

Status

()

Firefox
Developer Tools: Performance Tools (Profiler/Timeline)
VERIFIED FIXED
3 years ago
3 years ago

People

(Reporter: paul, Assigned: paul)

Tracking

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

Firefox Tracking Flags

(firefox36 verified)

Details

Attachments

(1 attachment, 8 obsolete attachments)

(Assignee)

Description

3 years ago
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
(Assignee)

Updated

3 years ago
Component: Developer Tools → Developer Tools: Timeline
(Assignee)

Comment 1

3 years ago
I'm planning to use console.time("XXX"); console.timeEnd("XXX");
Assignee: nobody → paul
(Assignee)

Updated

3 years ago
Depends on: 1071056
(Assignee)

Updated

3 years ago
Depends on: 1071183
(Assignee)

Comment 2

3 years ago
Created attachment 8493755 [details] [diff] [review]
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.
(Assignee)

Comment 3

3 years ago
Created attachment 8494442 [details] [diff] [review]
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.
Attachment #8493755 - Attachment is obsolete: true
Attachment #8494442 - Flags: feedback?(ttromey)
(Assignee)

Comment 4

3 years ago
Created attachment 8494444 [details] [diff] [review]
v1

Sorry. Wrong patch.
Attachment #8494442 - Attachment is obsolete: true
Attachment #8494442 - Flags: feedback?(ttromey)
Attachment #8494444 - Flags: feedback?(ttromey)
(Assignee)

Comment 5

3 years ago
(commit message in the patch is wrong)
(Assignee)

Comment 6

3 years ago
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).
(Assignee)

Comment 7

3 years ago
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.
(Assignee)

Comment 8

3 years ago
Created attachment 8494479 [details] [diff] [review]
v2

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 9

3 years ago
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+
(Assignee)

Comment 10

3 years ago
(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

3 years ago
> 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.
(Assignee)

Comment 12

3 years ago
(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+
(Assignee)

Comment 14

3 years ago
Created attachment 8495198 [details] [diff] [review]
v3
Attachment #8494479 - Attachment is obsolete: true
Attachment #8495198 - Flags: review?(vporof)
Attachment #8495198 - Flags: review?(pbrosset)
(Assignee)

Comment 15

3 years ago
Created attachment 8495202 [details] [diff] [review]
v3

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)
(Assignee)

Comment 16

3 years ago
(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.
(Assignee)

Comment 17

3 years ago
Created attachment 8495234 [details] [diff] [review]
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.
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+
(Assignee)

Comment 19

3 years ago
> ::: 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.
(Assignee)

Comment 20

3 years ago
(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+
(Assignee)

Comment 23

3 years ago
(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.
(Assignee)

Comment 24

3 years ago
> @@ +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.
(Assignee)

Comment 25

3 years ago
Victor, ignore comment 23, I thought you were talking about sorting.
(Assignee)

Comment 26

3 years ago
Created attachment 8495799 [details] [diff] [review]
v3 (r=vporof,r=pbrosset)

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+
(Assignee)

Comment 28

3 years ago
(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.
(Assignee)

Comment 29

3 years ago
(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.
(Assignee)

Comment 30

3 years ago
Created attachment 8510077 [details] [diff] [review]
v3 (r=vporof,r=pbrosset,r=baku)

Rebased. Addressed Andrea's comment.
Attachment #8495799 - Attachment is obsolete: true
Attachment #8510077 - Flags: review+
(Assignee)

Comment 31

3 years ago
https://tbpl.mozilla.org/?tree=Try&rev=29d00b9f95fe
(Assignee)

Updated

3 years ago
Keywords: checkin-needed
https://hg.mozilla.org/integration/fx-team/rev/da2f24716a5e
Keywords: checkin-needed
Whiteboard: [fixed-in-fx-team]
https://hg.mozilla.org/mozilla-central/rev/da2f24716a5e
Status: NEW → RESOLVED
Last Resolved: 3 years ago
Resolution: --- → FIXED
Whiteboard: [fixed-in-fx-team]
Target Milestone: --- → Firefox 36
status-firefox36: --- → fixed
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
status-firefox36: fixed → 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)
You need to log in before you can comment on or make changes to this bug.