922221 - Add console.timeStamp

Status: RESOLVED FIXED

(DevTools :: Console, enhancement, P2)

Description

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

https://github.com/DeveloperToolsWG/console-object/blob/master/api.md#consoletimestamplabel

> This method adds an event to the Timeline during a recording session. This lets
> you visually correlate your code generated time stamp to other events, such as
> screen layout and paints, that are automatically added to the Timeline.

Comment 1

[Peter Gasston]

This is a duplicate of 884125 https://bugzilla.mozilla.org/show_bug.cgi?id=884125

Comment 2

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

I construed that to be adding support to the netmonitor UI (as opposed to the profiler or console) while this one is for actually implementing the method on the console object. Updated the relationship to reflect this better.

Comment 3

[Peter Gasston]

(In reply to Nick Fitzgerald [:fitzgen] from comment #2)
> I construed that to be adding support to the netmonitor UI (as opposed to
> the profiler or console) while this one is for actually implementing the
> method on the console object. Updated the relationship to reflect this
> better.

Oh, you’re right, my apologies.

Comment 4

[Jordan Santell [:jsantell] [@jsantell]]

Attachment: 899753-timestamp.patch

Added console.timeStamp() to fire off TimelineMarkers.

Notes: 
* This is my first C++ patch so please tear apart and ensure I didn't do anything terrible.
* Tests for the TimelineMarker creation, as well as ConsoleEvent creation.
* Should this have its own ConsoleEvent struct like ConsoleTimerStart/ConsoleTimerEnd? The base object ConsoleEvent covers all necessary fields (arguments, timeStamp, level).
* This seems to be the first TimelineMarker of its kind to not really have a duration value, just a single point in time. Should probably consider maybe changing TimelineMarker to support that in the future? For now, just creates both a start and stop marker immediately after each other.
* time/timeEnd require an argument to label them (although, Chrome doesn't, and this may be a future bug), but timeStamp() should not. I have some weird logic in there to handle whether or not an argument is passed that I'm sure can be better, but not sure how that works.

What kind of tests should I run on try for this?

Comment 5

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Comment on attachment 8579492 [details] [diff] [review]
899753-timestamp.patch

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

::: dom/base/Console.cpp
@@ +788,5 @@
> +  Sequence<JS::Value> data;
> +  SequenceRooter<JS::Value> rooter(aCx, &data);
> +
> +  if (!aData.isUndefined()) {
> +    data.AppendElement(aData);

This looks right.

@@ +1079,5 @@
>        }
>  
> +      // 'timeStamp' recordings do not need an argument
> +      if (isTimelineRecording && aMethodName == MethodTimeStamp) {
> +        if (aData.Length() == 0) {

You say you're having issues with "undefined" when you call console.timeStamp() with no arguments. So is this condition never true for you? I'd think that conditionally adding the parameter to the sequence data behind `if (!data.isUndefined())` check above would handle this.

Can you verify that you aren't hitting this branch, and that the ToString call in the other branch is indeed the one giving you "undefined"?

It looks like you're handling this stuff properly, at a glance. I wouldn't be surprised if this bug was actually happening down the pipe in some JS code somewhere.

I guess you could always try `if (aData.Length() == 0 || aData[0].isUndefined())` but if that doesn't fix it, then the bug is definitely down the line.

@@ +1089,5 @@
> +            nsAutoJSString key;
> +            if (key.init(aCx, jsString)) {
> +              mozilla::UniquePtr<TimelineMarker> marker =
> +                MakeUnique<TimestampTimelineMarker>(docShell, TRACING_INTERVAL_START, key);
> +              docShell->AddProfileTimelineMarker(marker);

Aside/unrelated: it seems strange to me that AddProfileTimelineMarker doesn't take ownership of the marker... Need to read some code to figure out what's up here.

Comment 6

[Tom Tromey :tromey]

Comment on attachment 8579492 [details] [diff] [review]
899753-timestamp.patch

(In reply to Jordan Santell [:jsantell] [@jsantell] from comment #4)
> Created attachment 8579492 [details] [diff] [review]
> 899753-timestamp.patch
> 
> Added console.timeStamp() to fire off TimelineMarkers.
> 
> Notes: 
> * This is my first C++ patch so please tear apart and ensure I didn't do
> anything terrible.

Nice!  I didn't see anything bad at all.

> * Should this have its own ConsoleEvent struct like
> ConsoleTimerStart/ConsoleTimerEnd? The base object ConsoleEvent covers all
> necessary fields (arguments, timeStamp, level).
> * This seems to be the first TimelineMarker of its kind to not really have a
> duration value, just a single point in time. Should probably consider maybe
> changing TimelineMarker to support that in the future? For now, just creates
> both a start and stop marker immediately after each other.

I think my ideal would be to keep TimestampTimelineMarker (as you have),
but use TRACING_EVENT rather than TRACING_INTERVAL_START, and only have
a single call to AddProfileTimelineMarker.

Then, nsDocShell::PopProfileTimelineMarkers would have to be updated to
handle TRACING_EVENT.  And since we push other TRACING_EVENTS that we don't
want to pop in isolation (see FrameLayerBuilder.cpp:LayerTimelineMarker),
another special case in there would be needed; like say some new virtual
method on TimelineMarker.

I'd check with smaug before embarking on this, perhaps, since last time around
he was concerned with the proliferation of special cases.  Though it's also
worth pointing out that this would be useful when we deal with emitting
console.time/timeEnd as separate events.

I guess this route would need more changes in js as well, to handle the new
case where a marker has a start time but no end time.

> * time/timeEnd require an argument to label them (although, Chrome doesn't,
> and this may be a future bug), but timeStamp() should not. I have some weird
> logic in there to handle whether or not an argument is passed that I'm sure
> can be better, but not sure how that works.

Me neither :}

> What kind of tests should I run on try for this?

Another thing I'd like to know myself.

Comment 7

[Jordan Santell [:jsantell] [@jsantell]]

Comment on attachment 8579492 [details] [diff] [review]
899753-timestamp.patch

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

::: dom/base/Console.cpp
@@ +1079,5 @@
>        }
>  
> +      // 'timeStamp' recordings do not need an argument
> +      if (isTimelineRecording && aMethodName == MethodTimeStamp) {
> +        if (aData.Length() == 0) {

Sorry, to clarify, I was having the issue of "undefined" string, but got around it with this in the patch -- just wasn't sure if there was a nicer way to do this. I definitely should check for the first element being undefined though, and test `console.timeStamp(undefined)` in that case

Comment 8

[Jordan Santell [:jsantell] [@jsantell]]

(In reply to Tom Tromey :tromey from comment #6)
> Comment on attachment 8579492 [details] [diff] [review]
> 899753-timestamp.patch
> 
> (In reply to Jordan Santell [:jsantell] [@jsantell] from comment #4)
> > Created attachment 8579492 [details] [diff] [review]
> > 899753-timestamp.patch
> > 
> > Added console.timeStamp() to fire off TimelineMarkers.
> > 
> > Notes: 
> > * This is my first C++ patch so please tear apart and ensure I didn't do
> > anything terrible.
> 
> Nice!  I didn't see anything bad at all.
> 
> > * Should this have its own ConsoleEvent struct like
> > ConsoleTimerStart/ConsoleTimerEnd? The base object ConsoleEvent covers all
> > necessary fields (arguments, timeStamp, level).
> > * This seems to be the first TimelineMarker of its kind to not really have a
> > duration value, just a single point in time. Should probably consider maybe
> > changing TimelineMarker to support that in the future? For now, just creates
> > both a start and stop marker immediately after each other.
> 
> I think my ideal would be to keep TimestampTimelineMarker (as you have),
> but use TRACING_EVENT rather than TRACING_INTERVAL_START, and only have
> a single call to AddProfileTimelineMarker.
> 
> Then, nsDocShell::PopProfileTimelineMarkers would have to be updated to
> handle TRACING_EVENT.  And since we push other TRACING_EVENTS that we don't
> want to pop in isolation (see FrameLayerBuilder.cpp:LayerTimelineMarker),
> another special case in there would be needed; like say some new virtual
> method on TimelineMarker.

> I'd check with smaug before embarking on this, perhaps, since last time
> around
> he was concerned with the proliferation of special cases.  Though it's also
> worth pointing out that this would be useful when we deal with emitting
> console.time/timeEnd as separate events.

I'd say that the layering is more of a special case than a marker that only has one time value. Outside of console methods, I can imagine other scenarios where we'd be interested in just a single value of an event occurring. If we have TimelineMarkers that consist only a name ("Timestamp"), metadata (TRACING_EVENT) and a cause (arbitrary string/undefined), that'd cover all the console scenarios atleast ("Timestamp", "TimeStart", "TimeEnd", etc), and we can check for is a marker TRACING_EVENT && aName != "Layer" in the marker loop, as that seems like the biggest special case, rather than the other way around.

> I guess this route would need more changes in js as well, to handle the new
> case where a marker has a start time but no end time.

That's true, but that's pretty straight forward -- more difficult part is having a special rule for TimeStart/TimeEnd when they're different markers, and correlating them, but still doable

> > * time/timeEnd require an argument to label them (although, Chrome doesn't,
> > and this may be a future bug), but timeStamp() should not. I have some weird
> > logic in there to handle whether or not an argument is passed that I'm sure
> > can be better, but not sure how that works.
> 
> Me neither :}
> 
> > What kind of tests should I run on try for this?
> 
> Another thing I'd like to know myself.

@smaug
Thoughts on using TRACING_EVENTS for TimelineMarkers that only have one time value? LayerTimelineMarkers can remain the special use case, but this would allow us to have multiple markers for console.time/timeEnd, as well as not having both TRACING_INTERVAL_START and TRACING_INTERVAL_END for a single-valued "timestamp"

Comment 9

[Olli Pettay [:smaug][[e-mail]]]

Hmm, I'm a bit lost how this all would work. Why does console API depend here on whether we're recording timeline? How would the setup work for iframes and such? I assume we usually record
only top level content docshells.
(I'm not familiar with Bug 1050502, which added some existing stuff there.)

Comment 10

[Jordan Santell [:jsantell] [@jsantell]]

Looks like AddProfileTimelineMarkers checks to see if there's a timeline recording before adding the marker anyway, so that may be redundant. But without a recording timeline, there's no need for markers in the first place (as far as I know?)

Currently, console.time/timeEnd works with iframes (iframe emits console.time/timeEnd, and the console displays the timer messages, and if recording, the markers appear on the devtools timeline).

Comment 11

[Olli Pettay [:smaug][[e-mail]]]

Ok, so we somehow mark also iframes to be recording. I guess the setup is fine then - assuming we
need the information only when recording.
And regarding TRACING_EVENTS use... whatever makes the code easiest to understand and maintain.
(this isn't particularly performance hot code)

Comment 12

[Tom Tromey :tromey]

(In reply to Olli Pettay [:smaug] from comment #9)
> Hmm, I'm a bit lost how this all would work. Why does console API depend
> here on whether we're recording timeline? 

It's normal for code using a subclass of TimelineMarker to check the docshell first,
to avoid an allocation in the case where the marker is simply going to be deleted.

Comment 13

[Olli Pettay [:smaug][[e-mail]]]

I was mainly wondering how we deal with subframes.

Comment 14

[Jordan Santell [:jsantell] [@jsantell]]

Attachment: 922221-timestamp.patch

Thanks all for the feedback!

Updating the PopProfileTimelineMarker method, if this is a TRACING_EVENT (and not Layer, as that's a special scenario), a new marker (in this case "Timestamp") is emitted, with identical start/end times, and also in this case, optional label. The front end can handle this fine (once it's updated to listen to Timestamp markers).

Kyle, I heard you might be a good person to review this; if not, let me know! The tests in this patch pass, but also if there are ideal try flags to run for these directories (platform newb here), I'll give those a go as well.

Thanks!

Comment 15

[Tom Tromey :tromey]

(In reply to Jordan Santell [:jsantell] [@jsantell] from comment #14)

> Updating the PopProfileTimelineMarker method, if this is a TRACING_EVENT
> (and not Layer, as that's a special scenario), a new marker (in this case
> "Timestamp") is emitted, with identical start/end times, and also in this
> case, optional label. The front end can handle this fine (once it's updated
> to listen to Timestamp markers).

I think it would be good for TimestampTimelineMarker to try to capture a
stack trace in its constructor.  It can just call CaptureStack() unconditionally.
Then the new code in docshell could put the stack on the marker object.

Comment 16

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Comment on attachment 8579765 [details] [diff] [review]
922221-timestamp.patch

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

You need to test this in workers too.  Look at dom/workers/test/test_console.html.  r- for that, but this looks pretty good otherwise.

::: dom/base/Console.cpp
@@ +1066,5 @@
>      }
>    }
>  
>    // Monotonic timer for 'time' and 'timeEnd'
> +  if ((aMethodName == MethodTime || aMethodName == MethodTimeEnd || aMethodName == MethodTimeStamp)) {

Wrap at 80 characters please.

@@ +1102,5 @@
> +                MakeUnique<TimestampTimelineMarker>(docShell, TRACING_EVENT, key);
> +              docShell->AddProfileTimelineMarker(marker);
> +            }
> +          }
> +        }

Why not write this as

 if (isTimelineRecording && aMethodName == MethodTimeStamp) {
   JS::Rooted<JS::Value> value(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_EVENT, key);
   docShell->AddProfileTimelineMarker(marker);
}

Comment 17

[Tom Tromey :tromey]

(In reply to Kyle Huey [:khuey] ([e-mail]) from comment #16)
> Comment on attachment 8579765 [details] [diff] [review]
> 922221-timestamp.patch
> 
> Review of attachment 8579765 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> You need to test this in workers too.  Look at
> dom/workers/test/test_console.html.  r- for that, but this looks pretty good
> otherwise.

FWIW currently workers can't post markers to the timeline.

Comment 18

[Jordan Santell [:jsantell] [@jsantell]]

Attachment: 922221-timestamp.patch

* Wrapped lines to <80
* TimestampTimelineMarker now only has one constructor
* Removed if/else logic for when there are no arguments (or undefined) given; using the snippet you wrote, Kyle, but using JS_GetEmptyStringValue, as otherwise the jsString would be cast to strings of "0" or "undefined"
* Added test in the worker to ensure this doesn't throw (but it doesn't/shouldn't do anything yet anyway in a worker)

Once bug 1144820 lands, this will need a 2 character fix or something. What's the desired try command to run tests touching all of these components?

Thanks!

Comment 19

[Jordan Santell [:jsantell] [@jsantell]]

Attachment: 922221-timestamp.patch

Added the changes from bug 1144820 necessary, and changed MOZ_OVERRIDE to override.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=521185667d64

Comment 20

[Jordan Santell [:jsantell] [@jsantell]]

New try, didn't have bug 1144820 on there, oops:  https://treeherder.mozilla.org/#/jobs?repo=try&revision=da24c769660c

Comment 21

[Jordan Santell [:jsantell] [@jsantell]]

Moving dev-doc-needed to bug 1143004, as this doesn't do anything without the front end

Comment 22

[Jordan Santell [:jsantell] [@jsantell]]

Seeing weird AsyncShutdown failures on last try, trying again with a latest hg pull -u https://treeherder.mozilla.org/#/jobs?repo=try&revision=f87cd88a7564

Comment 23

[Jordan Santell [:jsantell] [@jsantell]]

Attachment: 922221-timestamp.patch

Was failing a test on the timeline front end, as the Layer marker was being emitted. Changed to check to see if it's not Layer or Paint before emitting if its a TRACING_EVENT (meaning an event with one time, rather than two) -- not elegant, but wonder what a better way of indicating this marker does not have a matching pair.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=df9218ad29af

Comment 24

[Jordan Santell [:jsantell] [@jsantell]]

Comment on attachment 8585142 [details] [diff] [review]
922221-timestamp.patch

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

Removing review -- strange failure on password manager?
https://treeherder.mozilla.org/#/jobs?repo=try&revision=df9218ad29af

Comment 25

[Tom Tromey :tromey]

(In reply to Jordan Santell [:jsantell] [@jsantell] from comment #23)
> Created attachment 8585142 [details] [diff] [review]
> 922221-timestamp.patch
> 
> Was failing a test on the timeline front end, as the Layer marker was being
> emitted. Changed to check to see if it's not Layer or Paint before emitting
> if its a TRACING_EVENT (meaning an event with one time, rather than two) --
> not elegant, but wonder what a better way of indicating this marker does not
> have a matching pair.

FWIW I think you don't have to check !isPaint.  "Paint" markers should always
be paired.  Sorry I missed this earlier, I think I confused the Paint and Layer
cases.

Also, since you've added isLayer, I think it would be good to change the later
strcmp(endMarkerName, "Layer") == 0 to simply use isLayer as well.

One way to make this cleaner might be to have the TimelineMarker object decide
for itself whether it should be emitted.  This could be a new boolean member,
a virtual function, or perhaps even a new TRACING_* constant.

Comment 26

[Jordan Santell [:jsantell] [@jsantell]]

My original assumptions of TRACING_EVENT being a "one timestamp event with no pairing" was incorrect, because of the layer and paint events, hence the reason for all the checks, which isn't great, as future markers may also be added here, and if we want to make it easy for one-time events to be implemented by others, this makes it more confusing/difficult.

What is the connotation of the TRACING_EVENT/START/END properties? If it doesn't make sense for that to also mean "a one time event", then adding a bool memory/function is probably the best way to go

Comment 27

[Tom Tromey :tromey]

(In reply to Jordan Santell [:jsantell] [@jsantell] from comment #26)
> My original assumptions of TRACING_EVENT being a "one timestamp event with
> no pairing" was incorrect, because of the layer and paint events, hence the
> reason for all the checks, which isn't great, as future markers may also be
> added here, and if we want to make it easy for one-time events to be
> implemented by others, this makes it more confusing/difficult.

Yeah.

> What is the connotation of the TRACING_EVENT/START/END properties? If it
> doesn't make sense for that to also mean "a one time event", then adding a
> bool memory/function is probably the best way to go

The enum constants were just reused from the profiling code and made to fit.
This also explains the name of some methods ("PopProfileTimelineMarkers" - it
doesn't really have anything to do with profiling per se) and some other old
stuff (no longer in tree).

Dropping the use of TracingMetadata in favor of a new enum solely for these
markers would be fine with me.  Then Layer could just have its own special constant.

I think the meaning of the constants is just as you assume; with the caveat that
there is this hack for Layer markers due to how the Paint/Layer markers interact.

Comment 28

[Jean-Yves Perrier [:teoli]]

(In reply to Jordan Santell [:jsantell] [@jsantell] from comment #21)
> Moving dev-doc-needed to bug 1143004, as this doesn't do anything without
> the front end

Setting dev-doc-needed back. As far as I understand the patch, this change a webidl that is exposed.

Comment 29

[Panos Astithas (he/him) [:past] (please ni?)]

Blocks a P2, so I'm updating the priority to reflect that.

Comment 30

[Jordan Santell [:jsantell] [@jsantell]]

Attachment: 922221-timestamp.patch

Created new TracingMetadata, TRACING_TIMESTAMP, for single time value markers
https://treeherder.mozilla.org/#/jobs?repo=try&revision=e212e3db45fd

Comment 31

[Jordan Santell [:jsantell] [@jsantell]]

Comment on attachment 8599476 [details] [diff] [review]
922221-timestamp.patch

Ok, switched to using TRACING_TIMESTAMP for the single-value marker, and doesn't conflict with the other markers using TRACING_EVENT. Kyle, can you give this one more look over? Tests looking good.

Comment 32

[Jordan Santell [:jsantell] [@jsantell]]

Kyle, any chance you could look at this next week?

Comment 33

[Jordan Santell [:jsantell] [@jsantell]]

Thanks, Kyle!
Landed: https://hg.mozilla.org/integration/fx-team/rev/641fcb51bd9a

Tom, pinging you here so you're aware of the TRACING_TIMESTAMP for a single value marker which could be useful elsewhere.

Comment 34

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/641fcb51bd9a

Comment 35

[Tom Tromey :tromey]

(In reply to Jordan Santell [:jsantell] [@jsantell] from comment #33)
> Thanks, Kyle!
> Landed: https://hg.mozilla.org/integration/fx-team/rev/641fcb51bd9a
> 
> Tom, pinging you here so you're aware of the TRACING_TIMESTAMP for a single
> value marker which could be useful elsewhere.

Thanks for the heads up.

Comment 36

[Will Bamberg [:wbamberg]]

I've added:
- a page on this in the Console docs: https://developer.mozilla.org/en-US/docs/Web/API/Console/timeStamp
- a section in the Waterfall docs: https://developer.mozilla.org/en-US/docs/Tools/Performance/Waterfall#Timestamp_markers

Let me know if this works for you.

Comment 37

[Jordan Santell [:jsantell] [@jsantell]]

Looks great, Will; thanks!