1386495 - Include event timeStamp with DOMEvent marker

Status: RESOLVED FIXED

(Core :: Gecko Profiler, enhancement)

Description

[Kan-Ru Chen [:kanru] (UTC+9)]

+++ This bug was initially created as a clone of Bug #1371528 +++

Useful for automated analysis and highlighting when events are waiting longer.

The gecko part should add DOMEvent::mTimeStamp to DOMEventMarkerPayload and the front end part can show the info in timeline view first.

We can figure out how to incorporate the latency into the tracing timeline later.

Comment 1

[Kan-Ru Chen [:kanru] (UTC+9)]

Attachment: Bug 1386495 - Add timeStamp to DOMEventMarkerPayload.

Review commit: https://reviewboard.mozilla.org/r/164288/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/164288/

Comment 2

[Kan-Ru Chen [:kanru] (UTC+9)]

The timeStamp field is optional. I'm not sure if I should bump the profile version.

Comment 3

[Markus Stange [:mstange]]

Comment on attachment 8893249 [details]
Bug 1386495 - Add timeStamp to DOMEventMarkerPayload.

https://reviewboard.mozilla.org/r/164288/#review170118

Optional properties don't need a version change.

In general I prefer optional properties to always exist and just be null in the case where there's no value, but doing that *would* require a version change (because then you'd want consumers to be able to rely on the field being present always). So let's take your patch as-is.

Comment 4

[Kan-Ru Chen [:kanru] (UTC+9)]

Olli, I'd like you to review this to make sure I added the right thing.

The idea is the profiler front-end should be able to get the event latency by (payload.startTime - payload.timeStamp)

Comment 5

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

Comment on attachment 8893249 [details]
Bug 1386495 - Add timeStamp to DOMEventMarkerPayload.

https://reviewboard.mozilla.org/r/164288/#review170222

I think the recorded time is wrong.
Don't you want more like TimeStamp::Now() - aEvent->mTimeStamp?
Or perhaps I just misunderstand what is wanted here.

Btw, I wonder why we add marker in HandleEventInternal. That means each event listeners adds a marker. Shouldn't this marker be added in EventDispatcher::Dispatch after the event has been dispatched or so?

::: tools/profiler/core/ProfilerMarkerPayload.cpp:104
(Diff revision 1)
>                                       UniqueStacks& aUniqueStacks)
>  {
>    StreamCommonProps("DOMEvent", aWriter, aProcessStartTime, aUniqueStacks);
> +  if (!mTimeStamp.IsNull()) {
> +    aWriter.DoubleProperty("timeStamp",
> +                           (mTimeStamp - aProcessStartTime).ToMilliseconds());

I don̈́'t understand this one. Why are we using process start time for anything?
(or does aProcessStartTime mean something else?)

Comment 6

[Kan-Ru Chen [:kanru] (UTC+9)]

(In reply to Olli Pettay [:smaug] from comment #5)
> Comment on attachment 8893249 [details]
> Bug 1386495 - Add timeStamp to DOMEventMarkerPayload.
> 
> https://reviewboard.mozilla.org/r/164288/#review170222
> 
> I think the recorded time is wrong.
> Don't you want more like TimeStamp::Now() - aEvent->mTimeStamp?
> Or perhaps I just misunderstand what is wanted here.

startTime is TimeStamp::Now() recorded earlier so it looks correct.
 
> Btw, I wonder why we add marker in HandleEventInternal. That means each
> event listeners adds a marker. Shouldn't this marker be added in
> EventDispatcher::Dispatch after the event has been dispatched or so?

Ha! That explains why I saw multiple marker of the same event on the timeline.
Maybe when the code was added it makes sense to mark each event listener's handle time?

> ::: tools/profiler/core/ProfilerMarkerPayload.cpp:104
> (Diff revision 1)
> >                                       UniqueStacks& aUniqueStacks)
> >  {
> >    StreamCommonProps("DOMEvent", aWriter, aProcessStartTime, aUniqueStacks);
> > +  if (!mTimeStamp.IsNull()) {
> > +    aWriter.DoubleProperty("timeStamp",
> > +                           (mTimeStamp - aProcessStartTime).ToMilliseconds());
> 
> I don̈́'t understand this one. Why are we using process start time for
> anything?
> (or does aProcessStartTime mean something else?)

I guess this is how the profiler works. All time recorded are relative to the process start time in the profile.

Comment 7

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

> > ::: tools/profiler/core/ProfilerMarkerPayload.cpp:104
> > (Diff revision 1)
> > >                                       UniqueStacks& aUniqueStacks)
> > >  {
> > >    StreamCommonProps("DOMEvent", aWriter, aProcessStartTime, aUniqueStacks);
> > > +  if (!mTimeStamp.IsNull()) {
> > > +    aWriter.DoubleProperty("timeStamp",
> > > +                           (mTimeStamp - aProcessStartTime).ToMilliseconds());
> > 
> > I don̈́'t understand this one. Why are we using process start time for
> > anything?
> > (or does aProcessStartTime mean something else?)
> 
> I guess this is how the profiler works. All time recorded are relative to
> the process start time in the profile.
Then I don't understand what kinds of time durations we're recording.

Comment 8

[Markus Stange [:mstange]]

In the profile JSON, all timestamps are expressed as "milliseconds since process start", and profile.meta.startTime has the absolute process start time.
So this is just how you convert a timestamp (not a duration) into the format that the profile uses.

Comment 9

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

But the timestamp can be coming from different process.

Comment 10

[Markus Stange [:mstange]]

True, so the code at https://github.com/devtools-html/perf.html/blob/e0b0f451873e5948378731120ae2e46d257cd789/src/profile-logic/process-profile.js#L574-L579 will also need to be adjusted.

Comment 11

[:Harald Kirschner :digitarald]

> Ha! That explains why I saw multiple markers of the same event on the timeline. Maybe when the code was added it makes sense to mark each event listener's handle time?

Not sure if I understand correctly; is this causing overlapping markers? Just to clarify, one marker per event listener being called is the expected behavior.

Comment 12

[Kan-Ru Chen [:kanru] (UTC+9)]

So based on the feedback,

 1. One marker per event listener being called is the expected behavior. It doesn't causing overlapping markers.
 2. I should adjust the timeStamp field in post processing when I update the profiler front-end.

requesting review again from Olli.

Comment 13

[Kan-Ru Chen [:kanru] (UTC+9)]

Ah, I can't request re-review from mozreview. Please see comment 12.

Comment 14

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

Comment on attachment 8893249 [details]
Bug 1386495 - Add timeStamp to DOMEventMarkerPayload.

https://reviewboard.mozilla.org/r/164288/#review170792

OK, http://searchfox.org/mozilla-central/rev/b52285fffc13f36eca6b47de735d4e4403b3859e/tools/profiler/core/ProfilerMarkerPayload.cpp#23-31 does something similar.
I don't fully understand why this all works that way, but maybe it is fine, even if event's timestamp is from parent process, but start and end times are from child.

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/c3692bad764d
Add timeStamp to DOMEventMarkerPayload. r=mstange,smaug

Comment 16

[Carsten Book [:Tomcat]]

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

Comment 17

[Aki Sasaki (not active)]

https://hg.mozilla.org/projects/date/rev/c3692bad764d5eadb0f8adf69eeb8aca8643ac83
Bug 1386495 - Add timeStamp to DOMEventMarkerPayload. r=mstange,smaug