Include event timeStamp with DOMEvent marker

RESOLVED FIXED in Firefox 57

Status

()

RESOLVED FIXED
a year ago
3 months ago

People

(Reporter: kanru, Assigned: kanru)

Tracking

unspecified
mozilla57
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox57 fixed)

Details

Attachments

(1 attachment)

(Assignee)

Description

a year ago
+++ 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 hidden (mozreview-request)
(Assignee)

Comment 2

a year ago
The timeStamp field is optional. I'm not sure if I should bump the profile version.
Flags: needinfo?(mstange)

Comment 3

a year ago
mozreview-review
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.
Attachment #8893249 - Flags: review?(mstange) → review+
(Assignee)

Updated

a year ago
Attachment #8893249 - Flags: review?(bugs)
(Assignee)

Comment 4

a year ago
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)
Flags: needinfo?(mstange) → needinfo?(bugs)

Comment 5

a year ago
mozreview-review
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?)
Attachment #8893249 - Flags: review?(bugs) → review-
(Assignee)

Comment 6

a year ago
(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.
> > ::: 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.
Flags: needinfo?(bugs)
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.
But the timestamp can be coming from different process.
> 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.
(Assignee)

Comment 12

a year ago
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.
(Assignee)

Comment 13

a year ago
Ah, I can't request re-review from mozreview. Please see comment 12.
Flags: needinfo?(bugs)

Comment 14

a year ago
mozreview-review
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.
Attachment #8893249 - Flags: review- → review+

Comment 15

a year ago
Pushed by kchen@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/c3692bad764d
Add timeStamp to DOMEventMarkerPayload. r=mstange,smaug

Comment 16

a year ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/c3692bad764d
Status: NEW → RESOLVED
Last Resolved: a year ago
status-firefox57: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla57
Flags: needinfo?(bugs)
Assignee: nobody → kanru
You need to log in before you can comment on or make changes to this bug.