1177226 - Support User Timing API events in the Developer HUD

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Developer Tools, defect)

Description

[Jan Keromnes [:janx]]

Many interesting performance markers are sent by web apps using the User Timing API[1], such as the "visuallyLoaded" and "contentInteractive" events[2].

It might be interesting to add a UserTimingWatcher to the HUD, even if mostly for logging and telemetry purposes (I'm not sure that overlay widgets would make sense for this). 

[1] User Timing API http://www.w3.org/TR/user-timing/
[2] "performance.mark" calls in Gaia https://github.com/mozilla-b2g/gaia/search?utf8=%E2%9C%93&q=performance.mark&type=Code

Comment 1

[Russ Nicoletti [:russn]]

Hi Jan, can you provide an overview of what is required for this? I think primarily around adding the actor and the actor communicating to the HUD (hud.js). Providing app startup metrics is the top priority for nga telemetry. It would be helpful to us if I could begin to move it forward while you're on vacation. Thanks.

Comment 2

[Jan Keromnes [:janx]]

Hi Russ, for this you would need to:

- Add an actor in /toolkit/devtools/server/actors/ (or use an existing actor, e.g. I think performance actors do collect some markers from a Console API, maybe it makes sense to complement these actors? I don't really know, but you could ask :vporof or :jsantell).

That actor will live in every child process being created, and you could then add a userTimingWatcher object in /b2g/chrome/content/devtools/hud.js (similar to the other watchers, which use specific actors to get their metrics).

It will be the job of that watcher to choose which metrics to report, so for example it will listen to "appLaunch@xxx" events from the Homescreen, keep track of them, and diff them with "visuallyComplete" events from the particular app that was launched. Then, it can report a single metric "launchTime" about that app.

For more specific questions, feel free to ask :jryans (he will either know the answer or who to ask). Good luck!

Comment 3

[Russ Nicoletti [:russn]]

Hi Eli, I've been reading the raptor wiki to try to understand Jan's comment 2. I have some questions:

1) Does the homescreen use gaia_grid to launch applications and therefore create 'appLaunch' + appContext performance markers for each app being launched or is that raptor-specific?
2) If yes, how do I get access to the 'appLaunch' + appContext performance marks created by the homescreen (i.e., gaia_grid). My understanding is getEntriesByType returns performance mark information only for the app from which it is being called. Is there actually an event emitted when a mark is created as Jan's comment implies? I don't see any evidence of an event being emitted in the code.

Comment 4

[:Eli Perelman]

Hey Russ,

1. Yes, the homescreen uses gaia_grid to launch applications and it creates the appLaunch marker. This marker isn't Raptor-specific.

2. In order to have access to this mark outside of the homescreen, it needs to be sent to the System. We discussed this in Whistler, and the goal is to have one of the actors or some other mechanism emit an event from Gecko that will only be received by System for performance marks that are created in any application. This functionality does not yet exist.

Comment 5

[Russ Nicoletti [:russn]]

jryans, the developer HUD has been updated to include support for collecting and sending telemetry information. We'd like to continue augmenting the HUD backend (the actors and hud.js) to include user timing events for the purposes of telemetry. Jan gives his implementation overview in comment 2; what's missing for me is how the actor will get access to the performance markers. Can you provide some guidance here? It would seem the performance "mark" API should emit an event with the performance entry information for the actor to consume. Is there a better way? If going that route, it looks like "PerformanceBase::Mark" is the appropriate place to emit the event, do you agree?

One last question: can you point me to an example of a cpp actor communicating information to hud.js? That would be very helpful. Thanks.

Comment 6

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

(In reply to Russ Nicoletti [:russn] from comment #5)
> jryans, the developer HUD has been updated to include support for collecting
> and sending telemetry information. We'd like to continue augmenting the HUD
> backend (the actors and hud.js) to include user timing events for the
> purposes of telemetry. Jan gives his implementation overview in comment 2;
> what's missing for me is how the actor will get access to the performance
> markers. Can you provide some guidance here? It would seem the performance
> "mark" API should emit an event with the performance entry information for
> the actor to consume. Is there a better way? If going that route, it looks
> like "PerformanceBase::Mark" is the appropriate place to emit the event, do
> you agree?

For your use case, do you need to know about the timing mark immediately after it's created?  I am a little wary of triggering an event right after creating a performance mark, since that could add processing overhead to any subsequent timings, which could make the data collection less accurate.

Would it instead be possible to wait until some known event (I am not sure if this exists for your use case or not), and then go collect all existing performance marks via "performance.getEntriesByType("mark")"?

> One last question: can you point me to an example of a cpp actor
> communicating information to hud.js? That would be very helpful. Thanks.

There are no DevTools actors in C++, they are all in JS.  So, if we need to get data from C++ land, it needs to expose some API to JS, emit an event, etc.

Comment 7

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

Jordan, you may have thoughts on this topic.  IIRC, the performance tool does not currently include "performance.mark" calls in the timeline today, is that correct?

Is there an existing actor it would make sense to add this to?  I guess for the performance tool, you may want it as part of the profiler's JSON blob?  If so, I guess the HUD may need a separate approach here.

Anyway, just curious if you have opinions here.

Comment 8

[:Eli Perelman]

If we can, I'd like to postpone progress on this until I can raise an issue about performance metrics with some of the stakeholders. I've found a somewhat serious issue with how metrics are gathered in Raptor, and it may mean we abandon the usage of the appLaunch marker in homescreen having a measurement context in separate applications. If that's the case, :jryans's remarks about using performance.getEntries may be the best option, by waiting until the application has hit fullyLoaded.

I should know more tomorrow on the direction we need to go for measuring app launch performance, and I'll report back here.

:jryans: if you are interested, we've got progress towards a PerformanceObserver interface [1], which may come of use. :)

[1] https://w3c.github.io/performance-timeline/#the-performance-observer-interface

Comment 9

[Russ Nicoletti [:russn]]

If we can't rely on the homescreen appLaunch marker for the "app launch start time", how would using performance.getEntries help? Don't we still need to relate the app performance markers to some "app launch start time"? My understanding is raptor is doing that by utilizing the fact that gecko is logging not just the marker's "startTime" but the epoch of when the marker was created -- therefore raptor can relate the appLaunch marker to the app's markers via the epoch of these markers.

For telemetry, if we can't find a better way, we will use the existing time-to-load metric that is currently being captured by the developer HUD.

Comment 10

[:Eli Perelman]

getEntries wouldn't be a replacement for appLaunch, basically we would swap out al the performance.marks for measures which would change the app launch start time to performance.timing.navigationStart. The mechanism you use to get these values shouldn't change, only the fact that you won't have to do manual delta calculations yourself, it will be handled for you by performance.measure. Does that make sense?

Comment 11

[Russ Nicoletti [:russn]]

If we have access to "performance.timing.navigationStart" it should be trivial for us to do the delta calculation as opposed to changing all the performance.mark calls to performance.measure. However, I have found that code that uses "performance.timing.navigationStart" doesn't execute. For example, this log entry in my js actor doesn't appear whereas the one immediately before it does appear: "console.log('PerformanceTiming, fetchStart: ' + performance.timing.fetchStart);". I've also tried "performance.fetchStart" and "Performance.fetchStart". Not sure what's happening.

Comment 12

[:Eli Perelman]

Just to update here, Raptor is going to continue to use the appLaunch Homescreen mark as it does today. Please ignore my comments in comment 8 and proceed as planned. :)

Comment 13

[Russ Nicoletti [:russn]]

Eli, is raptor using the Homescreen mark, that is, the "startTime" or is it using the epoch of when the mark was created? If it's using the startTime of the mark, how does it relate that to the app's fullyLoaded startTime? My understanding is you can't relate one app's performance marks to another app's performance marks.

:jryans, would writing the performance mark information to the console via the console API be less obtrusive than sending an event? If the performance mark information is stored via the console API, the hud (hud.js) would be able to access to it.

Eli, I assume the performance mark information is being written directly to the adb log instead of using the console API is because the console API is not as efficient in terms of performance. Is that why the console API is not being used in this case?

Comment 14

[:Eli Perelman]

(In reply to Russ Nicoletti [:russn] from comment #13)
> Eli, is raptor using the Homescreen mark, that is, the "startTime" or is it
> using the epoch of when the mark was created? If it's using the startTime of
> the mark, how does it relate that to the app's fullyLoaded startTime? My
> understanding is you can't relate one app's performance marks to another
> app's performance marks.

Hey Russ, yes, Raptor gathers epochs because you cannot relate the High-Res timings generated in one process with another. Basically, Raptor assumes all marks are measures during launch and manually does the duration calculation by comparing the epochs of the mark and the appLaunch mark.

> Eli, I assume the performance mark information is being written directly to
> the adb log instead of using the console API is because the console API is
> not as efficient in terms of performance. Is that why the console API is not
> being used in this case?

Yes, the feedback I received was that developers didn't want their console filling up with logs of performance entries since there could be many of them. The performance of console was also a concern. By putting User Timing entry logging behind a pref and outputting to logcat, we avoid both of those situations.

Comment 15

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

(In reply to Russ Nicoletti [:russn] from comment #13)
> :jryans, would writing the performance mark information to the console via
> the console API be less obtrusive than sending an event? If the performance
> mark information is stored via the console API, the hud (hud.js) would be
> able to access to it.

It's not a good idea sending random things through the console API.  Only calls to actual console methods should be going through there.

The reasoning is that:

* It would be surprising to developers to see random messages that did not come from true calls to the console APIs
* These messages are performance sensitive, so it's likely best to avoid overheard where possible, and processing the Console API is a form of overheard

So, if there is no way to wait until all marks have been made before collecting data, then something like PerformanceObserver interface, or else some internal event or observer API is needed, so that JS code be notified of a new performance marks / measures as they happen.

If there is a way to wait until some defined "everything is done now" moment, that is probably the simplest approach, and least likely to add overheard to the timings themselves.

Eli, I do not entirely follow the discussions in comments 8 - 14.  Is there some kind of "everything is done now" event that could be used to trigger collection of all the other timings?

Comment 16

[:Eli Perelman]

There are no events, only performance marks. If we emit an event at the same fullyLoaded is hit, then we lose our guarantee that nothing else will be executed after that point. That is why I suggested performance entries could, for now at least, emit an event in the System app, e.g. performanceentry. Thoughts?

Comment 17

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

Sorry for any confusion, I am new to this general topic.

(In reply to :Eli Perelman from comment #16)
> There are no events, only performance marks. If we emit an event at the same
> fullyLoaded is hit, then we lose our guarantee that nothing else will be
> executed after that point.

I am not sure I follow why it matters that more code runs after loading is done...  The only code chrome scope DevTools code to pull the various timings needed.  Why is it bad to perform these steps at this stage?

> That is why I suggested performance entries
> could, for now at least, emit an event in the System app, e.g.
> performanceentry. Thoughts?

Okay, you're suggesting that the DOM code for each call to e.g. performance.mark / measure would cause this event to be emitted to the System app?

Comment 18

[:Eli Perelman]

(In reply to J. Ryan Stinnett [:jryans] (use ni?) from comment #17)
> Sorry for any confusion, I am new to this general topic.

No worries!

> I am not sure I follow why it matters that more code runs after loading is
> done...  The only code chrome scope DevTools code to pull the various
> timings needed.  Why is it bad to perform these steps at this stage?

If the code that runs doesn't occur within the context of the application that is being run, I suppose that is OK. Raptor cannot reliably measure the memory of an application, or indicate that the cold-launch phase is complete and its OK to kill an app though if there is more work being done in the app. 

> Okay, you're suggesting that the DOM code for each call to e.g.
> performance.mark / measure would cause this event to be emitted to the
> System app?

Yes, e.g.:

```js
// In Clock
performance.mark('fullyLoaded');

// In System
window.addEventListener('performanceentry', function(e) {
  console.log(e); // { timeStamp, data: { name, startTime, duration, ... } }
});
```

PerformanceObserver is not yet ready, but we are meeting about it tomorrow and maybe we can set a goal for its recommendation. :)

Comment 19

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

(In reply to :Eli Perelman from comment #18)
> > I am not sure I follow why it matters that more code runs after loading is
> > done...  The only code chrome scope DevTools code to pull the various
> > timings needed.  Why is it bad to perform these steps at this stage?
> 
> If the code that runs doesn't occur within the context of the application
> that is being run, I suppose that is OK. Raptor cannot reliably measure the
> memory of an application, or indicate that the cold-launch phase is complete
> and its OK to kill an app though if there is more work being done in the
> app.

Alright.  Overall, I would be fine with either approach:

A. Wait for "fullyLoaded" and then pull all timings

or

B. Emit an event as each timing is created and record it then

Either way, there is some amount of extra work being done to collect timings and report them.  With A, you defer the extra work until after fullyLoaded (which should give slightly more accurate timings since the work is deferred until after the last measurement), and with B you pay for some work with each timing.

Approach A sounds slightly more efficient to me, but again I don't feel strongly about it.

A sketch of approach A would look like:

1. HUD code waits for someone to say "fullyLoaded" has happened (either a System event or the PerformanceObserver)
2. An new actor allows HUD code to pull all existing performance timings at once

A sketch of approach B would look like:

1. A new actor is created that allows watching for new performance marks (either a System event or the PerformanceObserver)
2. HUD code tells the actor to notify it of new timings
3. For each timing that comes in, the actor reports it to the HUD for recording

So, it seems like both A and B need a way to know when these steps are happening.  For A, it would just be the "fullyLoaded" step.  For B, it's each individual timing.  A System app event could work for now, and we could trasition to the PerformanceObserver once that exists.

Comment 20

[Russ Nicoletti [:russn]]

Eli, correct me if I'm mistaken but it seems to me approach A doesn't work for us because what we really need is the epoch of the when performance marks are created, not just the performance mark information.

I have a working implementation for approach B. When gecko creates a performance mark entry, it sends a 'performanceentry' event that contains the mark name, the origin or the mark, and the epoch of when the mark was created. The event is received by a new 'StartupTimings' actor. 

The 'StartupTimings' actor in the homescreen context gets the 'appLaunch' event ('appLaunch' marks are only created by the homescreen) and sends an 'app-launch-start' event with the name of the app being launched and the epoch to a new 'startupTimings' HUD watcher. 

The 'StartupTimings' actors that run in an app's context listen to 'performanceentry' events and emit a 'performanceentry-hud' event with the origin, mark name, and epoch to the HUD 'startupTimings' watcher.

The HUD startupTimings watcher matches the origin of the 'performanceentry' events to the app name of the 'app-launch-start' event and calculates the delta between the epochs of each event.

Fyi, I measured the performance impact of gecko sending an event after creating a performance mark. Out of some 300 performance marks created, there was an average of 16ms impact by creating/sending an event.

I think this may be a feasible approach for telemetry purposes until the PerformanceObserver is available.

Comment 21

[:Eli Perelman]

(In reply to Russ Nicoletti [:russn] from comment #20)
> Eli, correct me if I'm mistaken but it seems to me approach A doesn't work
> for us because what we really need is the epoch of the when performance
> marks are created, not just the performance mark information.

Correct, for A to work you would need an object that has both the origin, epoch, and the Performance Entry object. B will work with each event as they come in since you can access event.timeStamp to get an epoch, although you still have to do the work of getting the origin. Looks like you are handling that in the rest of your implementation.

Comment 22

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

Sounds reasonable to me overall.  I am hopeful that the actor could be made more general than this specific case of startup timings, but that will be easier to say for sure during review.

Comment 23

[Russ Nicoletti [:russn]]

Attachment: bug-1177226.patch

Hi jryans, I made one change after my last comment in this bug. I changed the way I'm notifying observers of the 'performanceentry' event. I'm using the EventLoopLagDispatcher as a model since using a separate thread will minimize the performance impact of creating subsequent performance marks. Anyway, please let me know what you think of the patch. Thanks.

Comment 24

[Russ Nicoletti [:russn]]

Attachment: bug-1177226.patch

Minor updates to previous patch.

Comment 25

[Russ Nicoletti [:russn]]

Attachment: bug-1177226.patch

Needed to make some adjustments after getting the latest gecko code.

Comment 26

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

Comment on attachment 8635755 [details] [diff] [review]
bug-1177226.patch

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

I am not a DOM peer, so you'll need a separate review for the changes to files in /dom/base.  I would suggest checking recent reviewers of nsPerformance.cpp for ideas, as I don't know who has experience in this area.  You can also consult the peer list for the DOM module[1].  For future rounds, it may help to break up the DOM parts into one patch, and the DevTools part in another, since they'll have separate reviewers.

The more I look at this, the more I wonder if we should expose this data the same way we do for other timeline markers in the performance tool.  This would allow the performance tool to surface these timings in its timeline view, which sounds quite nice to me.

Let me talk more with Jordon who works on performance for DevTools about this.  Sorry for the confusion.

[1]: https://wiki.mozilla.org/Modules/Core#Document_Object_Model

::: dom/base/nsContentUtils.cpp
@@ +553,5 @@
>                                 "dom.event.handling-user-input-time-limit",
>                                 1000);
>  
> +  Preferences::AddBoolVarCache(&sSendPerformanceTimingNotifications,
> +                               "dom.performance.enable_advanced_telemetry_timing", true);

This pref's name should be about performance timing, since it is a general feature that is not specific to telemetry.

The default state of the pref should be defined in modules/libpref/init/all.js.  I would think we want default false, not true?  B2G (which I would guess is the only user for now?) can then set the default to true in b2g/app/b2g.js.

::: toolkit/devtools/server/actors/user-timings.js
@@ +38,5 @@
> +    }
> +  },
> +
> +  /**
> +   * Start tracking the event loop lags.

Need to update the comments.

@@ +47,5 @@
> +      Services.obs.addObserver(this, 'performanceentry', false);
> +      this._observerAdded = true;
> +    }
> +  }, {
> +    request: {},

When the request / response keys are empty, you can leave them out, as empty object is the default.

@@ +48,5 @@
> +      this._observerAdded = true;
> +    }
> +  }, {
> +    request: {},
> +    response: {success: RetVal("number")}

Seems like there is not actually any response value?

@@ +52,5 @@
> +    response: {success: RetVal("number")}
> +  }),
> +
> +  /**
> +   * Stop tracking the event loop lags.

Need to update the comments.

@@ +59,5 @@
> +    if (this._observerAdded) {
> +      Services.obs.removeObserver(this, 'performanceentry');
> +      this._observerAdded = false;
> +    }
> +  }, {request: {},response: {}}),

If they are both {}, you can omit the entire object that contains them.

@@ +61,5 @@
> +      this._observerAdded = false;
> +    }
> +  }, {request: {},response: {}}),
> +
> +  destroy: function() {

Unfortunately actor destruction is really confusing currently...  In any case, for an actor like this which is the first to be managed by protocol.js (this is what the line "this.manage(this);" means), you should also define "disconnect" so it is cleaned up properly when the connection closes:

  disconnect: function() {
    this.destroy();
  },

See the layout actor[1] as an example.

[1]: https://dxr.mozilla.org/mozilla-central/source/toolkit/devtools/server/actors/layout.js#71

@@ +68,5 @@
> +  },
> +
> +  // nsIObserver
> +
> +  observe: function (subject, topic, data) {

I don't think an observer is right fit here.  This actor should specific to the tab, app, etc. that it is associated with, but observers are global to all of Gecko.  Using an observer here means that:

1. Each tab, app, etc. will have an instance of this actor
2. Each actor instance will start its own observer but is listening for events from the whole system, not just one tab, app, etc.

It seems like this would lead to data being reported multiple times, since every app installs the same observer.

I think a better design would be to use a chrome-only event, since this can be specific to a document.  An example of this is DOMWindowCreated[1].

However, this may change depending on if we decide to make this be more like performance timeline markers.

[1]: https://dxr.mozilla.org/mozilla-central/source/dom/base/nsGlobalWindow.cpp#2775

@@ +73,5 @@
> +
> +    let ORIGIN_IDX = 0;
> +    let MARK_IDX = 1;
> +    let VALUE_IDX = 2; 
> +    if (topic === "performanceentry") {

DevTools actors try to "generic" and describe page resources and web features at a general level, without being specific to one particular tool or way of using the data.  

So, in this case, the actor should be simple and emit any performance entries as they come in.  Then, hud.js would decide whether specific entries are interesting for your specific case.

This way, the actor can be reused for other purposes later.

Comment 27

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

Jordan, in this bug we're discussing ways to expose call "performance.mark" (the User Timing API[1]) via the DevTools.

The Firefox OS team wants to use this data via the DevTools HUD (on-screen debug tools for Firefox OS) and package it up for telemetry.

We could make a new actor for this specific web feature, or we could try to expose the timings as markers that the timeline actor would pick up.  

If they are timeline markers, it seems nice that they would also appear in the performance tool by default.  However, then the HUD tool would be listening for all timeline markers, and would need to filter down to just these timing ones that it cares about.

Do you have any opinions on which way we proceed?

[1]: http://www.w3.org/TR/user-timing/

Comment 28

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

Russ / Eli, I know the main focus of the work here is about collecting performance.mark for telemetry via the HUD.

Would you also like the .mark() calls to appear in the DevTools Performance tool's timeline?  Similar APIs like console.timeStamp() appear there today.  I think it could be quite nice, but I wasn't sure if this is valuable to you.

If it is valuable, then one course of action is to record performance.mark similar to console.timeStamp[1].  This would make them appear in the Performance tool automatically.  Then for the DevTools HUD / telemetry, it would act as a client of the timeline actor to process these markers.

I know we discussed several approaches already.  It's a bit tricky since we have several ways to do very similar things, so I'm just trying understand the best approach.

[1]: https://dxr.mozilla.org/mozilla-central/source/dom/base/Console.cpp?from=console.cpp&case=true#1188

Comment 29

[:Eli Perelman]

Yes, User Timing entries should also show up in the performance timeline. I had discussed this on dev-b2g a while back and Paul responded with this:

https://groups.google.com/d/msg/mozilla.dev.b2g/NSnBDfmRG9o/PLqn6VeVU8MJ

I can't speak for implementation details, only that this was ultimately one of the major plans behind User Timing entries.

Comment 30

[Russ Nicoletti [:russn]]

For telemetry purposes, exposing performance mark information is a benefit but not the main requirement. In fact, we won't be exposing the performance mark information in the intial telemetry implementation. We're only using the performance marks to deduce app startup time. The approach I've implemented (comment 25) is not simply making use of performance marks, it is making use of the epoch of when the marks are created. These epochs can be related to each other. This is also what raptor is doing. I'm assuming the epochs of the performance marks will not available via the performance timeline via 'AddProfileTimelineMarker', only the performance mark information.

One question about the timeline actor (perhaps more a question about the performance timeline itself), timeline.js mentions a "memory" event. What information is contained in this event? What is the purpose of the event? I'm thinking it may be useful for telemetry purposes. We want to get app memory usage at the "fullyLoaded" marker. Would these timeline memory events allow us to do that?

Comment 31

[Russ Nicoletti [:russn]]

(In reply to J. Ryan Stinnett [:jryans] (use ni?) from comment #26)
> Comment on attachment 8635755 [details] [diff] [review]
> bug-1177226.patch
> 
> Review of attachment 8635755 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> > +  // nsIObserver
> > +
> > +  observe: function (subject, topic, data) {
> 
> I don't think an observer is right fit here.  This actor should specific to
> the tab, app, etc. that it is associated with, but observers are global to
> all of Gecko.  Using an observer here means that:
> 
> 1. Each tab, app, etc. will have an instance of this actor
> 2. Each actor instance will start its own observer but is listening for
> events from the whole system, not just one tab, app, etc.
> 
> It seems like this would lead to data being reported multiple times, since
> every app installs the same observer.
> 
> I think a better design would be to use a chrome-only event, since this can
> be specific to a document.  An example of this is DOMWindowCreated[1].
> 
> However, this may change depending on if we decide to make this be more like
> performance timeline markers.
> 
> [1]:
> https://dxr.mozilla.org/mozilla-central/source/dom/base/nsGlobalWindow.
> cpp#2775
> 
Ok, I wasn't aware of the difference between notifying an observer vs. using a chrome-only event. I'm not very familiar with sending events from gecko. I saw that the event loop gecko code (toolkit/xre/EventTracer.cpp) is notifying the event loop lag actor via an observer so I used the same pattern. If using an observer was going to result in data being reported multiple times, wouldn't that problem also occur with event loop lag? Regarding user-timings data potentially being reported multiple times, this is not happening based on my testing. Based on what you've explained, I'm not sure why data is not reported multiple times. What happens to the actors corresponding to background apps? It seems somehow they are not active. I'm not sure how else to explain why data is not being reported multiple times.

Regarding using chrome-only events, from looking at examples in the code, I don't see them being used to send a payload along with the event. Is it possible to send a payload with a chrome-only event? I need to send the mark name, the epoch, and the origin (the app generating the event) along with the event.

Comment 32

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

(In reply to Russ Nicoletti [:russn] from comment #30)
> For telemetry purposes, exposing performance mark information is a benefit
> but not the main requirement. In fact, we won't be exposing the performance
> mark information in the intial telemetry implementation. We're only using
> the performance marks to deduce app startup time. The approach I've
> implemented (comment 25) is not simply making use of performance marks, it
> is making use of the epoch of when the marks are created. These epochs can
> be related to each other. This is also what raptor is doing. I'm assuming
> the epochs of the performance marks will not available via the performance
> timeline via 'AddProfileTimelineMarker', only the performance mark
> information.

That seems correct to me, `AddProfileTimelineMarker` only captures a single time point (console.timeStamp, similar to performance.mark's startTime) or a start / end pair (similar to performance.measure).

Since you need the epoch to relate times across processes, I think for now it's best to proceed with a separate solution here, and avoid the DevTools timeline marker system.

After some more discussion on #devtools, we realized another issue for DevTools timeline markers today is that the timeline actor drains a queue of markers, so if someone tried to use the DevTools perf tool while the HUD wanted the same data, it could lead to only one client (HUD vs. DevTools) getting the info.

So, let's do our own thing for this bug.

For the implementation, a chrome-only event still seems correct to me, like I hinted in comment 26.  Since you need to express the startTime, epoch, etc. you'll want to add custom detail to the event.  Most examples I've seen do this from JS, but here's a C++ example from DOMWindowResize[1].

I do think you'll eventually want User Timing marks in the DevTools perf timeline for a better developer user experience, but we'll worry about that separately from this bug.  I filed bug 1186580 for this work.

> One question about the timeline actor (perhaps more a question about the
> performance timeline itself), timeline.js mentions a "memory" event. What
> information is contained in this event? What is the purpose of the event?
> I'm thinking it may be useful for telemetry purposes. We want to get app
> memory usage at the "fullyLoaded" marker. Would these timeline memory events
> allow us to do that?

The timeline actor's memory event is capturing the same memory value as the MemoryFront.measure() call already in hud.js[2], so you can already make use of such data without the timeline actor.

[1]: https://dxr.mozilla.org/mozilla-central/source/dom/base/nsGlobalWindow.cpp#6100-6104
[2]: https://dxr.mozilla.org/mozilla-central/source/b2g/chrome/content/devtools/hud.js#704

Comment 33

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

(In reply to Russ Nicoletti [:russn] from comment #31)
> (In reply to J. Ryan Stinnett [:jryans] (use ni?) from comment #26)
> > Comment on attachment 8635755 [details] [diff] [review]
> > bug-1177226.patch
> > 
> > Review of attachment 8635755 [details] [diff] [review]:
> > -----------------------------------------------------------------
> > 
> > > +  // nsIObserver
> > > +
> > > +  observe: function (subject, topic, data) {
> > 
> > I don't think an observer is right fit here.  This actor should specific to
> > the tab, app, etc. that it is associated with, but observers are global to
> > all of Gecko.  Using an observer here means that:
> > 
> > 1. Each tab, app, etc. will have an instance of this actor
> > 2. Each actor instance will start its own observer but is listening for
> > events from the whole system, not just one tab, app, etc.
> > 
> > It seems like this would lead to data being reported multiple times, since
> > every app installs the same observer.
> > 
> > I think a better design would be to use a chrome-only event, since this can
> > be specific to a document.  An example of this is DOMWindowCreated[1].
> > 
> > However, this may change depending on if we decide to make this be more like
> > performance timeline markers.
> > 
> > [1]:
> > https://dxr.mozilla.org/mozilla-central/source/dom/base/nsGlobalWindow.
> > cpp#2775
> > 
> Ok, I wasn't aware of the difference between notifying an observer vs. using
> a chrome-only event. I'm not very familiar with sending events from gecko. I
> saw that the event loop gecko code (toolkit/xre/EventTracer.cpp) is
> notifying the event loop lag actor via an observer so I used the same
> pattern. If using an observer was going to result in data being reported
> multiple times, wouldn't that problem also occur with event loop lag?

Event loop lag is capturing something global to the entire process, which is a more natural fit for observers. Since you're accessing something specific to a particular app and not the entire Gecko runtime, I think a chrome-only event is a better fit.

> Regarding user-timings data potentially being reported multiple times, this
> is not happening based on my testing. Based on what you've explained, I'm
> not sure why data is not reported multiple times. What happens to the actors
> corresponding to background apps? It seems somehow they are not active. I'm
> not sure how else to explain why data is not being reported multiple times.

It's possible this is related to the B2G process model of putting each app in its own process.  Since adding a DevTools actor means adding a feature that could be used elsewhere (desktop Firefox, etc.), I think it's better to use the chrome events to avoid the potential for trouble.

> Regarding using chrome-only events, from looking at examples in the code, I
> don't see them being used to send a payload along with the event. Is it
> possible to send a payload with a chrome-only event? I need to send the mark
> name, the epoch, and the origin (the app generating the event) along with
> the event.

I think my last comment 32 should help here.

Comment 34

[Russ Nicoletti [:russn]]

Ok, I have made the gecko changes to send a custom event when a performance mark is created. As far as the actor changes, I'm unsure how to get the 'window' object on which to add the event listener. I see there are some actors that do this (e.g., webconsole, webbrowser), but I don't know if they are good models for the user-timings actor. What's the best way to do this?

Comment 35

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

Been talking to jryans about this in irc, and I think he answered the ni? for me; let me know otherwise!

Comment 36

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

(In reply to Russ Nicoletti [:russn] from comment #34)
> Ok, I have made the gecko changes to send a custom event when a performance
> mark is created. As far as the actor changes, I'm unsure how to get the
> 'window' object on which to add the event listener. I see there are some
> actors that do this (e.g., webconsole, webbrowser), but I don't know if they
> are good models for the user-timings actor. What's the best way to do this?

You can override `initialize` in your actor, as in gcli.js[1] and others, so you can hold onto the second arg `tabActor`.  This is your "parent actor" that represents the app (or tab on desktop, etc.).  It has a `window` property among others, so `tabActor.window` would give you want you need.

To add your listener though, I think you need the "chrome event handler", which should also be available on tabActor[2].  Here is an example listener being added[3].

The `tabActor` name can be confusing...  We are aiming to change and improve the names.  It really means "the main actor for the thing being debugged", such as a tab, app, process, etc.  We at least tried to document some of the naming recently[4].

[1]: https://dxr.mozilla.org/mozilla-central/source/toolkit/devtools/server/actors/gcli.js#31
[2]: https://dxr.mozilla.org/mozilla-central/source/toolkit/devtools/server/actors/webbrowser.js#766
[3]: https://dxr.mozilla.org/mozilla-central/source/toolkit/devtools/server/actors/storage.js#1696
[4]: https://dxr.mozilla.org/mozilla-central/source/toolkit/devtools/server/docs/actor-hierarchy.md

Comment 37

[Russ Nicoletti [:russn]]

Attachment: user-timings-hud.patch

This patch contains the hud-related changes for this bug (hud.js and the new actor). I will create another patch for the dom-related changes.

Comment 38

[Russ Nicoletti [:russn]]

Attachment: user-timings-hud.patch

Sorry for the confusion. I forgot to include a couple of files in the previous patch.

Comment 39

[Russ Nicoletti [:russn]]

Attachment: user-timings-dom.patch

The goal of this bug is to add telemetry metrics related to user timings. The idea is to emit an event when performance marks are created that is processed by the HUD. Currently, the HUD is only recording telemetry metrics, not displaying the information on the front-end.

Comment 40

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

Comment on attachment 8638745 [details] [diff] [review]
user-timings-dom.patch

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

::: dom/base/nsContentUtils.cpp
@@ +553,5 @@
>                                 "dom.event.handling-user-input-time-limit",
>                                 1000);
>  
> +  Preferences::AddBoolVarCache(&sSendPerformanceTimingNotifications,
> +                               "dom.performance.enable_notify_performance_timing", true);

The last arg is the default value, so it should be false.

Comment 41

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

Comment on attachment 8638715 [details] [diff] [review]
user-timings-hud.patch

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

Thanks for changing to the chrome events, I think it makes more sense now.

There are still some other pieces of my last review that need to be completed.

I'll be gone for a few days next week, so there may be a delay before I can do the next review.

::: toolkit/devtools/server/actors/user-timings.js
@@ +13,5 @@
> + */
> +
> +const {Ci, Cu} = require("chrome");
> +const Services = require("Services");
> +Cu.import("resource://gre/modules/XPCOMUtils.jsm");

No longer needed, since the QI can go away.

@@ +19,5 @@
> +  method, Arg, Option, RetVal, Front, FrontClass, Actor, ActorClass
> +} = require("devtools/server/protocol");
> +const events = require("sdk/event/core");
> +
> +let UserTimingsActor = exports.UserTimingsActor = ActorClass({

I can imagine this actor growing naturally in the future to include navigation and resource timing too.  Since actor names are locked down after they appear due to version compatibility requirements, I'm try to imagine the future a bit here.

How about the name "PerformanceEntriesActor" / "performance-entries.js"?  That seems like a reasonable umbrella name for these "window.performance" concepts.

@@ +47,5 @@
> +  /**
> +   * Start tracking the user timings.
> +   */
> +  start: method(function() {
> +

Nit: remove blank line

@@ +50,5 @@
> +  start: method(function() {
> +
> +    if (!this.listenerAdded) {
> +      let handler = this.tabActor.chromeEventHandler;
> +      handler.addEventListener("performanceentry", this.onPerformanceEntry.bind(this), true);

By using `bind` here, the later call to `removeEventListener` won't work correctly, because you would need to pass it the value `bind` returns.

Common techniques here include:

a. In #initialize, use `this.onPerformanceEntry = this.onPerformanceEntry.bind(this)` so that add and remove use the same value
b. Pass `this` to add and remove, add the method name `handleEvent`.  It will be called with the correct `this`, no bind needed.  You would check the event name, and call `onPerformanceEntry` from this method.

@@ +54,5 @@
> +      handler.addEventListener("performanceentry", this.onPerformanceEntry.bind(this), true);
> +      this.listenerAdded = true;
> +    }
> +  }, {
> +    request: {},

See comment 26 about omitting these when empty.

@@ +67,5 @@
> +      let handler = this.tabActor.chromeEventHandler;
> +      handler.removeEventListener("performanceentry", this.onPerformanceEntry, true);
> +      this.listenerAdded = false;
> +    }
> +  }, {request: {},response: {}}),

See comment 26 about omitting these when empty.

@@ +78,5 @@
> +    this.stop();
> +    Actor.prototype.destroy.call(this);
> +  },
> +
> +  onPerformanceEntry: function (e) {

See comment 26 about making this more generic.

@@ +100,5 @@
> +      eventName = 'performanceentry-hud';
> +    }
> +
> +    events.emit(this, eventName, emitDetail);
> +  }, 

Nit: trailing whitespace

@@ +101,5 @@
> +    }
> +
> +    events.emit(this, eventName, emitDetail);
> +  }, 
> +  QueryInterface: XPCOMUtils.generateQI([Ci.nsIObserver]),

This QI can be removed, since there are no longer any observers involved.

Comment 42

[Russ Nicoletti [:russn]]

Attachment: performance-entries-hud.patch

:jryans, thanks for all your feedback and review comments. With this patch I believe I have addressed everything.

Comment 43

[(no longer active)]

Comment on attachment 8638745 [details] [diff] [review]
user-timings-dom.patch

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

Please fix your coding style, the indentations etc are all over the place.

::: dom/base/nsContentUtils.cpp
@@ +553,5 @@
>                                 "dom.event.handling-user-input-time-limit",
>                                 1000);
>  
> +  Preferences::AddBoolVarCache(&sSendPerformanceTimingNotifications,
> +                               "dom.performance.enable_notify_performance_timing", true);

Yes.

::: dom/base/nsPerformance.cpp
@@ +41,5 @@
>  using namespace mozilla;
>  using namespace mozilla::dom;
>  using namespace mozilla::dom::workers;
>  
> +class PerformanceTimingDispatcher : public nsRunnable

Please make this final.

@@ +48,5 @@
> +    explicit PerformanceTimingDispatcher(const nsAString& type,
> +                                         const nsAString& name,
> +                                         uint64_t startTime,
> +                                         uint64_t duration,
> +                                         const nsAutoCString uri,

const nsACString&.

@@ +57,5 @@
> +        mStartTime(startTime),
> +        mDuration(duration),
> +        mMarkCreationEpoch(markCreationEpoch),
> +        mOwner(owner) {
> +          mUri = uri;

Why initialize this in the body of the ctor?

@@ +60,5 @@
> +        mOwner(owner) {
> +          mUri = uri;
> +        }
> +
> +    NS_IMETHODIMP Run()

Nit: override

@@ +64,5 @@
> +    NS_IMETHODIMP Run()
> +    {
> +      ErrorResult res;
> +      nsRefPtr<Event> domEvent =
> +        mOwner->GetDoc()->CreateEvent(NS_LITERAL_STRING("CustomEvent"), res);

Why are you creating the event like this?

@@ +78,5 @@
> +      detail.mStartTime = mStartTime;
> +      detail.mDuration = mDuration;
> +      detail.mOrigin = NS_ConvertUTF8toUTF16(mUri.get());
> +      detail.mEpoch = mMarkCreationEpoch;
> +      JS::Rooted<JS::Value> detailValue(cx);

This sucks.  Why don't you create a proper event type that has a proper UserTimingsEventDetail member?  (You should probably consult smaug before doing so, but what you're doing here is almost definitely undesirable.)

@@ +96,5 @@
> +
> +      domEvent->SetTrusted(true);
> +      domEvent->GetInternalNSEvent()->mFlags.mOnlyChromeDispatch = true;
> +
> +      nsCOMPtr<EventTarget> target = do_QueryInterface(mOwner->GetOuterWindow());

Why is the target the outer window?

@@ +105,5 @@
> +    }
> +
> +  private:
> +    const nsAString& mType;
> +    const nsAString& mName;

These shouldn't be references, since they will point to memory on the stack frame of nsPerformance::InsertUserEntry by the time this runs.  I'm pretty surprised this doesn't crash for you!

@@ +108,5 @@
> +    const nsAString& mType;
> +    const nsAString& mName;
> +    uint64_t         mStartTime;
> +    uint64_t         mDuration;
> +    nsAutoCString    mUri;

Please don't use nsAutoCString as a member.

@@ +110,5 @@
> +    uint64_t         mStartTime;
> +    uint64_t         mDuration;
> +    nsAutoCString    mUri;
> +    uint64_t         mMarkCreationEpoch;
> +    nsPIDOMWindow*   mOwner; 

This needs to be nsCOMPtr<nsPIDOMWindow>.

Comment 44

[Russ Nicoletti [:russn]]

(In reply to Ehsan Akhgari (not reviewing patches, not reading bugmail, needinfo? me!) from comment #43)
> Comment on attachment 8638745 [details] [diff] [review]
> user-timings-dom.patch
> 
> Review of attachment 8638745 [details] [diff] [review]:
> -----------------------------------------------------------------
 
> @@ +64,5 @@
> > +    NS_IMETHODIMP Run()
> > +    {
> > +      ErrorResult res;
> > +      nsRefPtr<Event> domEvent =
> > +        mOwner->GetDoc()->CreateEvent(NS_LITERAL_STRING("CustomEvent"), res);
> 
> Why are you creating the event like this?
> 
> @@ +78,5 @@
> > +      detail.mStartTime = mStartTime;
> > +      detail.mDuration = mDuration;
> > +      detail.mOrigin = NS_ConvertUTF8toUTF16(mUri.get());
> > +      detail.mEpoch = mMarkCreationEpoch;
> > +      JS::Rooted<JS::Value> detailValue(cx);
> 
> This sucks.  Why don't you create a proper event type that has a proper
> UserTimingsEventDetail member?  (You should probably consult smaug before
> doing so, but what you're doing here is almost definitely undesirable.)
> 

I was using the example provided by :jryans (comment 32) to create a custom event. 

:smaug, what do you recommend in terms of creating an event here? I'm creating an event with details of performance marks that will be handled by a HUD actor for the purposes of collecting telemetry information for firefox OS. Should I create a proper event ('UserTimingsEvent'?) or is it ok to use a "custom event"?

Comment 45

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

CustomEvent is rather painful to use in C++, because its .detail is 'any' which doesn't map well to C++ types.
So I'd be fine adding a new event interface for this.


Where is the event dispatched? ChromeOnly perhaps? Looks like so based on 
mFlags.mOnlyChromeDispatch = true;

Anyhow, I'd just add a new event interface and let event codegen to implement it.
(1) add a new YourNewFancyDevtoolsEvent.webidl. Add the interface for the event to it and mark the interface
[ChromeOnly]. Add also the dictionary for creating the event.
So something like http://mxr.mozilla.org/mozilla-central/source/dom/webidl/BlobEvent.webidl
but with [ChromeOnly] for the 'interface'.

(2) Then add the .webidl file to http://mxr.mozilla.org/mozilla-central/source/dom/webidl/moz.build
GENERATED_EVENTS_WEBIDL_FILES

(3) in your code you can then create and initialize the event similarly to 
http://mxr.mozilla.org/mozilla-central/source/dom/media/imagecapture/ImageCapture.cpp?rev=f1dd5e362984&mark=183-189#183
Though in your case you also want that mFlags.mOnlyChromeDispatch = true;



Will devtools need more custom event types? If so, perhaps we should have some generic devtools event which can then hold whatever data devtools need? But anyhow, for now, adding a particular event type for this case should be fine.

Comment 46

[Russ Nicoletti [:russn]]

Attachment: patch with PerformanceEntryEvent

Hi Olli, I've made the changes based on your feedback. However, I'm getting NS_ERROR_UNEXPECTED from DOMEventTargetHelper::DispatchEvent [1]. I'm not seeing any reason for this error based on my implementation compared to other DOM event implementations (e.g., http://mxr.mozilla.org/mozilla-central/source/dom/media/imagecapture/ImageCapture.cpp?rev=f1dd5e362984&mark=183-189#183). I will continue to investigate on my end. Btw, I don't see any errors or useful information in the adb log. I'd appreciate your feedback on this issue. Thanks.

1. http://mxr.mozilla.org/mozilla-central/source/dom/events/DOMEventTargetHelper.cpp#256

Comment 47

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

Comment on attachment 8640664 [details] [diff] [review]
patch with PerformanceEntryEvent

In the previous patch you dispatched event to Window, and in that case 
mFlags.mOnlyChromeDispatch = true; makes sense, since events propagate from
Window object to chrome.
But in this patch you dispatch event to Performance object, and with that
mFlags.mOnlyChromeDispatch = true; doesn't make sense.

I assume with the event target fixed  (and you need then dispatch the event
for example using EventTarget::DispatchEvent) I think this should work fine.

Comment 48

[Russ Nicoletti [:russn]]

I feel I need to take a step back. I originally started using an observer pattern where the devtools actor listened to notifications from nsPerformance::InsertUserEntry. :jryans didn't approve of the observer pattern, see below. Based on :jryans suggestion I switched to a custom event. While that may have been clumsily implemented (comment 43), it did work. Finally, your latest suggestion of using an event interface is cleaner but apparently requires a target object, which I don't have (I was able to send the event but the actor is not receiving it). In my case, the "target" is a document (see comment below from :jryans). My understanding from all of this is that I need to use a custom event that is chrome-only, similar to what I had implemented earlier (comment 39), similar to https://dxr.mozilla.org/mozilla-central/source/dom/base/nsGlobalWindow.cpp#6088. Does that makes sense?

(In reply to J. Ryan Stinnett [:jryans] (use ni?) (on PTO July 27 - 29) from comment #26)
> Comment on attachment 8635755 [details] [diff] [review]
> bug-1177226.patch
> 
> Review of attachment 8635755 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> > +
> > +  // nsIObserver
> > +
> > +  observe: function (subject, topic, data) {
> 
> I don't think an observer is right fit here.  This actor should specific to
> the tab, app, etc. that it is associated with, but observers are global to
> all of Gecko.  Using an observer here means that:
> 
> 1. Each tab, app, etc. will have an instance of this actor
> 2. Each actor instance will start its own observer but is listening for
> events from the whole system, not just one tab, app, etc.
> 
> It seems like this would lead to data being reported multiple times, since
> every app installs the same observer.
> 
> I think a better design would be to use a chrome-only event, since this can
> be specific to a document.  An example of this is DOMWindowCreated[1].
> 
> [1]:
> https://dxr.mozilla.org/mozilla-central/source/dom/base/nsGlobalWindow.
> cpp#2775
>

Comment 49

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

Wait what? Your target in the patch is not document.

My comment was about
DispatchTrustedEvent(perf_entry_event);
You dispatch event to window.performance object, not to window object as in the previous patch.

So change DispatchTrustedEvent(perf_entry_event); to something like
nsCOMPtr<EventTarget> et = do_QueryInterface(GetOwner());
if (et) {
  bool dummy = false;
  et->DispatchEvent(perf_entry_event, &dummy);
}



(random note, camelCase for variable names, so perfEntryEvent, not perf_entry_event)

Comment 50

[Russ Nicoletti [:russn]]

Attachment: emit performance entry event

Hi Ehsan, you'll find this patch a lot cleaner, after incorporating the feedback from :smaug.

Comment 51

[Russ Nicoletti [:russn]]

Attachment: process performance entry events

I'm canceling the previous review due to changes resulting from the feedback of the DOM cpp patch.

This patch should address your previous review comments and is consistent with the DOM patch review/feedback.

Comment 52

[(no longer active)]

Comment on attachment 8641277 [details] [diff] [review]
emit performance entry event

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

Much much better.  Thanks!

::: dom/base/nsPerformance.cpp
@@ +749,5 @@
>      }
> +    markCreationEpoch = static_cast<uint64_t>(PR_Now() / PR_USEC_PER_MSEC);
> +  }
> +
> +  if (nsContentUtils::IsUserTimingLoggingEnabled()) { 

Nit: trailing whitespace!

Comment 53

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

Comment on attachment 8641277 [details] [diff] [review]
emit performance entry event

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

::: dom/base/nsContentUtils.cpp
@@ +553,5 @@
>                                 "dom.event.handling-user-input-time-limit",
>                                 1000);
>  
> +  Preferences::AddBoolVarCache(&sSendPerformanceTimingNotifications,
> +                               "dom.performance.enable_notify_performance_timing", true);

See comment 40, this still needs to be changed to `false`.

::: dom/base/nsPerformance.cpp
@@ +760,5 @@
> +            markCreationEpoch);
> +  }
> +
> +  if (nsContentUtils::SendPerformanceTimingNotifications()) {
> +      PerformanceEntryEventInit init;

It seems like this file uses 2 space indent, not 4.

Comment 54

[Russ Nicoletti [:russn]]

Attachment: emit performance entry event

Fixed whitespace nit

Comment 55

[Russ Nicoletti [:russn]]

Attachment: emit performance entry event

Added reviewer to check-in comment

Comment 56

[Russ Nicoletti [:russn]]

Attachment: emit performance entry event

I've addressed your feedback from comment 53

Comment 57

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

Comment on attachment 8641360 [details] [diff] [review]
emit performance entry event

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

Thanks, looks like you've fixed the issues.

Comment 58

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

Comment on attachment 8641281 [details] [diff] [review]
process performance entry events

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

::: b2g/chrome/content/devtools/hud.js
@@ +602,5 @@
> +    this._client = client;
> +  },
> +
> +  trackTarget(target) {
> +

Nit: Remove this blank line

@@ +614,5 @@
> +    // User timings are always gathered; there is no setting to enable/
> +    // disable.
> +    front.start();
> +
> +    front.on('performanceentry-hud', detail => {

Update to match new actor event name.

@@ +622,5 @@
> +        let CHARS_UNTIL_APP_NAME = 7; // '@app://'
> +        if (name.indexOf('appLaunch') != -1) {
> +          let appStartPos = name.indexOf('@app') + CHARS_UNTIL_APP_NAME;
> +          let length = (name.indexOf('.') - appStartPos);
> +          this._appLaunchName = name.substr(appStartPos, length);

What's been your testing process to ensure this works?

It's not clear to me that it does as written because:

1. We should have a separate `performanceEntriesWatcher` instance per app
2. I thought only the Homescreen emitted `appLaunch@<app>`, so watching for `appLaunch` and saving `_appLaunchName` does not seem correct: only the Homescreen's instance of `performanceEntriesWatcher` would receive this
3. So, each app launch would likely clobber the previous value of `_appLaunchName`
and all the other marks (the `else` branch below) are received by instances of `performanceEntriesWatcher` for other apps, which would not have access to the value of `_appLaunchName`, so nothing would be sent

@@ +624,5 @@
> +          let appStartPos = name.indexOf('@app') + CHARS_UNTIL_APP_NAME;
> +          let length = (name.indexOf('.') - appStartPos);
> +          this._appLaunchName = name.substr(appStartPos, length);
> +          this._appLaunchStartTime = epoch;
> +        }

Nit: I think most Mozilla JS would use "} else {" here, or at least DevTools would

::: toolkit/devtools/server/actors/performance-entries.js
@@ +2,5 @@
> + * License, v. 2.0. If a copy of the MPL was not distributed with this
> + * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
> +
> +/**
> + * The performanceEntries actor emits an "app-launch-start" event when it receives 

Need to update this comment block, seems like much of it might be useful to have in hud.js.

@@ +23,5 @@
> +
> +  listenerAdded: false,
> +
> +  events: {
> +    "performanceentry-hud" : {

The actor is not hud specific, so the event does not need to be either.  Also, I think it's clear it's about performance since the actor name says that already.  So perhaps all we need is `entry` here?

@@ +28,5 @@
> +      type: "performanceentry-hud",
> +      detail: Arg(0, "json") // object containing origin of performance entry,
> +                             // performance entry name, epoch of performance entry.
> +    },
> +    "app-launch-start" : {

Remove this, you're not emitting this anymore.

@@ +77,5 @@
> +      name: e.name,
> +      origin: e.origin,
> +      epoch: e.epoch
> +    };
> +    events.emit(this, 'performanceentry-hud', emitDetail);

Update event name as above.

Comment 59

[Russ Nicoletti [:russn]]

(In reply to J. Ryan Stinnett [:jryans] (use ni?) from comment #58)
> Comment on attachment 8641281 [details] [diff] [review]
> process performance entry events
> 
> Review of attachment 8641281 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: b2g/chrome/content/devtools/hud.js
> 
> What's been your testing process to ensure this works?
> 
> It's not clear to me that it does as written because:
> 
> 1. We should have a separate `performanceEntriesWatcher` instance per app
> 2. I thought only the Homescreen emitted `appLaunch@<app>`, so watching for
> `appLaunch` and saving `_appLaunchName` does not seem correct: only the
> Homescreen's instance of `performanceEntriesWatcher` would receive this
> 3. So, each app launch would likely clobber the previous value of
> `_appLaunchName`
> and all the other marks (the `else` branch below) are received by instances
> of `performanceEntriesWatcher` for other apps, which would not have access
> to the value of `_appLaunchName`, so nothing would be sent
> 

I have been testing end-to-end, meaning I've been logging the performance entry events received by the performance entry actors and I've been logging the "AdvancedTelemetry" events from the hud.js, verifying the "app-start-time" events from the hud are consistent with the performance entry information received by the performance actors.

My understanding is that there is only one "watcher" and that each watcher is creating and starting the appropriate front per app (via `trackTarget`). This is the behavior I'm seeing when I added logging to investigate. Because the "appLaunch" mark will be immediately followed by performance entry marks for the app being launched, when the front for the app being launched receives performance entry events, `_appLaunchName` and `_appLaunchTime` will correspond to the name and the start time of the app that was just launched. Once the "appLaunch" mark event is received by the homescreen front, all the performance entry events received will come from the front corresponding to the app just launched and therefore the epoch of these events will be relative to `_appLaunchTime`.

Does this seem correct to you? It all works properly according to my testing and I believe the logic is sound.

Comment 60

[Russ Nicoletti [:russn]]

Attachment: process performance entry events

Patch updated based on most recent review comments.

Comment 61

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

(In reply to Russ Nicoletti [:russn] from comment #59)
> (In reply to J. Ryan Stinnett [:jryans] (use ni?) from comment #58)
> > Comment on attachment 8641281 [details] [diff] [review]
> > process performance entry events
> > 
> > Review of attachment 8641281 [details] [diff] [review]:
> > -----------------------------------------------------------------
> > 
> > ::: b2g/chrome/content/devtools/hud.js
> > 
> > What's been your testing process to ensure this works?
> > 
> > It's not clear to me that it does as written because:
> > 
> > 1. We should have a separate `performanceEntriesWatcher` instance per app
> > 2. I thought only the Homescreen emitted `appLaunch@<app>`, so watching for
> > `appLaunch` and saving `_appLaunchName` does not seem correct: only the
> > Homescreen's instance of `performanceEntriesWatcher` would receive this
> > 3. So, each app launch would likely clobber the previous value of
> > `_appLaunchName`
> > and all the other marks (the `else` branch below) are received by instances
> > of `performanceEntriesWatcher` for other apps, which would not have access
> > to the value of `_appLaunchName`, so nothing would be sent
> > 
> 
> I have been testing end-to-end, meaning I've been logging the performance
> entry events received by the performance entry actors and I've been logging
> the "AdvancedTelemetry" events from the hud.js, verifying the
> "app-start-time" events from the hud are consistent with the performance
> entry information received by the performance actors.
> 
> My understanding is that there is only one "watcher" and that each watcher
> is creating and starting the appropriate front per app (via `trackTarget`).

Okay, you're correct, sorry.  I re-read things again, and yes, there's only one watcher instance for all apps.

> This is the behavior I'm seeing when I added logging to investigate. Because
> the "appLaunch" mark will be immediately followed by performance entry marks
> for the app being launched, when the front for the app being launched
> receives performance entry events, `_appLaunchName` and `_appLaunchTime`
> will correspond to the name and the start time of the app that was just
> launched. Once the "appLaunch" mark event is received by the homescreen
> front, all the performance entry events received will come from the front
> corresponding to the app just launched and therefore the epoch of these
> events will be relative to `_appLaunchTime`.
> 
> Does this seem correct to you? It all works properly according to my testing
> and I believe the logic is sound.

Since there is only one watcher instance, I see a potential race condition if you start two apps quickly before the first finishes:

1. App A launches, setting `_appLaunchName` to A
2. App A emits a few performance marks which are stored correctly, but before finishing...
3. App B launches, setting `_appLaunchName` to B
4. App A emits more performance marks, but the watcher now ignores them since A != B in the watcher
5. App B emits performance marks which are stored correctly

Does this case matter to you?

Comment 62

[:Eli Perelman]

What do you plan to do with applications that are not launched via the homescreen? Will you discard entries that don't have a corresponding appLaunch?

Comment 63

[Russ Nicoletti [:russn]]

:jryans, good catch. I'd say the telemetry statistics won't be affected by very infrequently missing a couple of events. With that said, I don't think the fix will be very difficult so I would like to fix it. The way I'd like to approach this is to live with it in the initial check-in and create a bug that we can prioritize among the other telemetry bugs.

:Eli, yes, as of now we will disregard entries that don't have a corresponding appLaunch.

Comment 64

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

Comment on attachment 8641753 [details] [diff] [review]
process performance entry events

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

Okay, r+ assuming you update to address the remaining comments below.

::: b2g/chrome/content/devtools/hud.js
@@ +590,5 @@
>      }
>    }
>  };
>  developerHUD.registerWatcher(eventLoopLagWatcher);
> +/*

Nit: add blank line above the comment here for separation

@@ +635,5 @@
> +          this._appLaunchStartTime = epoch;
> +        } else {
> +          let origin = detail.origin;
> +          origin = origin.substr(0, origin.indexOf('.'));
> +          if (this._appLaunchName === origin) {

File a bug about the potential for dropped events when one app launches soon after another, and add a comment with the bug number.

Comment 65

[Russ Nicoletti [:russn]]

Attachment: process performance entry events

Addressing final review comments.

Comment 66

[Russ Nicoletti [:russn]]

Attachment: process performance entry events

Added review to check-in comment

Comment 67

[Russ Nicoletti [:russn]]

comment 66: s/review/reviewer

Comment 68

[Russ Nicoletti [:russn]]

Attachment: performance entry event

Combined the two patches ('emit performance entry events' and 'process performance entry events') into one patch.

Comment 69

[Ryan VanderMeulen [:RyanVM]]

Needs rebasing. Also, please provide a Try link.

Comment 70

[Russ Nicoletti [:russn]]

Attachment: rebased patch

This is the latest, rebased patch.

Comment 71

[Russ Nicoletti [:russn]]

Try server link: https://treeherder.mozilla.org/#/jobs?repo=try&revision=45f062014cf6

Comment 72

[Russ Nicoletti [:russn]]

There are some failures in the try test. They are known, intermittent failures or failures related to test infrastructure. I assume those are acceptable.

Comment 73

[Pulsebot]

https://hg.mozilla.org/integration/b2g-inbound/rev/105d5ff7b72c

Comment 74

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/105d5ff7b72c

Comment 76

[Russ Nicoletti [:russn]]

The list of performance marks currently used in gaia apps is: 

callLogStart
contentInteractive
firstChunkReady
fmRadioEnabled
ftuSkip
fullyLoaded
initialize
l10nready
loadEnd
loadSettingsStart
lockScreenLock
lockScreenUnlock
mediaEnumerated
navigationInteractive
navigationLoaded
objectsInitEnd
osLogoEnd
scanEnd
startupPathEnd
visuallyLoaded
wifiListStart
willRenderThreads