1145824 - Expose a getElapsedTime on nsIProfiler and allow getProfileData to filter by a start time

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect)

Description

[Shu-yu Guo [:shu]]

Right now the frontend devtools is jumping through hoops to figure out when a currently running instance of the profiler started by dumping the entire profile and computing the elapsed time of the oldest profile. Please let's not make them do this.

Comment 1

[Shu-yu Guo [:shu]]

s/oldest profile/oldest sample

Comment 2

[Shu-yu Guo [:shu]]

Attachment: Add getElapsedTime to nsIProfiler.

Comment 3

[Shu-yu Guo [:shu]]

Attachment: In nsProfiler, allow GetProfile and getProfileData to filter by a start time.

Comment 4

[Shu-yu Guo [:shu]]

Attachment: Use nsIProfiler's getElapsedTime instead of manually computing start time in the profiler actor.

Comment 5

[Shu-yu Guo [:shu]]

Attachment: Update the performance tool to use nsIProfiler's getElapsedTime and getProfileData's new filtering abilities.

Comment 6

[Shu-yu Guo [:shu]]

Attachment: Update the performance tool to use nsIProfiler's getElapsedTime and getProfileData's new filtering abilities.

Oops, accidentally committed some debugging stuff.

Comment 7

[Shu-yu Guo [:shu]]

Comment on attachment 8581043 [details] [diff] [review]
Update the performance tool to use nsIProfiler's getElapsedTime and getProfileData's new filtering abilities.

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

::: toolkit/devtools/server/actors/profiler.js
@@ +80,5 @@
>  
>    /**
>     * Stops the nsIProfiler module, if no other client is using it.
>     */
>    onStopProfiler: function() {

Oops, onStopProfiler is supposed to have gProfilingStartTime = 0 after nsIProfilerModule.StopProfiler().

Comment 8

[Shu-yu Guo [:shu]]

What ever stops the profiler? I don't see anything actually calling requesting "stopProfiler" on the profiler actor.

Comment 9

[Shu-yu Guo [:shu]]

Jordan, could you test with these patches if the problem still happens?

Comment 10

[Shu-yu Guo [:shu]]

Attachment: Fix tests.

I'm not sure how data-massaging-01 ever worked.

Comment 11

[Shu-yu Guo [:shu]]

Attachment: Update the performance tool to use nsIProfiler's getElapsedTime and getProfileData's new filtering abilities.

Sorry for the review churn.

This updated version removes gProfilingStartTime entirely. I left it in in the
last version for no good reason.

Comment 12

[Markus Stange [:mstange]]

Comment on attachment 8581012 [details] [diff] [review]
In nsProfiler, allow GetProfile and getProfileData to filter by a start time.

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

::: tools/profiler/ProfileEntry.cpp
@@ +274,5 @@
>      mWriter.EndObject();
>    }
>  };
>  
> +void ProfileBuffer::StreamSamplesToJSObject(JSStreamWriter& b, int aThreadId, float aSinceTime,

please add a line break before "float"

Comment 13

[Victor Porof [:vporof][:vp]]

(In reply to Shu-yu Guo [:shu] from comment #8)
> What ever stops the profiler? I don't see anything actually calling
> requesting "stopProfiler" on the profiler actor.

The only attempt to stop the profiler is on the backend, in the `disconnect` function in profiler.js. This is called as soon as a connection is closed, so when a toolbox is destroyed.

The frontend never calls `stopProfiler` manually while the toolbox, because we can't guarantee that there are no other consumers of this actor (e.g. other toolboxes, other profilers etc.). For simultaneous recordings, we rely on `isActive` and the "current" time to filter a profile.

It is not correct to simply count the number of calls to `startProfiler` and only actually stop the profiler when this reaches 0 (in `stopProfiler`), because `startProfiler` actually discards all the previously recorded data (basically throwing away the entire circular buffer). Therefore, we count the number of *connections* to the actor, and stop the profiler when all the connections close.

This doesn't guard against someone unexpectedly stopping the profiler module itself (e.g. addons not using the profiler actor, but accessing the nsIProfiler module directly).

Comment 14

[Victor Porof [:vporof][:vp]]

(In reply to Victor Porof [:vporof][:vp] from comment #13)
> 
> The frontend never calls `stopProfiler` manually while the toolbox, because

Typo: "while the toolbox *is open*"

Comment 15

[Victor Porof [:vporof][:vp]]

Comment on attachment 8581248 [details] [diff] [review]
Update the performance tool to use nsIProfiler's getElapsedTime and getProfileData's new filtering abilities.

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

r- mainly because I think the use of gLastConsoleProfileStartTime is incorrect. r+ if I'm wrong.

::: browser/devtools/performance/modules/front.js
@@ +266,5 @@
>     * @return object
>     *         A promise that is resolved once recording has stopped,
>     *         with the profiler and memory data, along with all the end times.
>     */
> +  stopRecording: Task.async(function*(startTime, options = {}) {

Rename this to profilerStartTime and add some documentation above. Would like to clearly state *why* this is necessary.

::: toolkit/devtools/server/actors/profiler.js
@@ +131,5 @@
>     *     } ... ]
>     *   } ... ]
>     * }
> +   *
> +   * @param number startTime

You and I know why startTime is needed, but contributors may not. Please add a line documenting its use.

@@ +248,5 @@
>            currentTime: 0
>          };
>        }
> +
> +      gLastConsoleProfileStartTime = currentTime;

I don't think this is correct. Suppose one does

console.profile("foo");
console.profile("bar");
console.profileEnd("foo");

In the second case, the profile range is between when "bar" started and "foo" stopped. Am I misreading this?

@@ -277,5 @@
>  /**
> - * Gets the time elapsed since the profiler was last started.
> - * @return number
> - */
> -function getElapsedTime() {

I AM SO HAPPY TO SEE THIS NUKED.

Comment 16

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

Comment on attachment 8581248 [details] [diff] [review]
Update the performance tool to use nsIProfiler's getElapsedTime and getProfileData's new filtering abilities.

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

::: toolkit/devtools/server/actors/profiler.js
@@ +248,5 @@
>            currentTime: 0
>          };
>        }
> +
> +      gLastConsoleProfileStartTime = currentTime;

Should the profiler actor manage the console.profiles? This lets someone start up the profiler without all of the other actors, but with the new performance tool, a console profile is compromised of several actors (timeline, memory, profiler). If we have the profiler back end also manage it, we'll have duplicated, or worse, inconsistent logic.

In the console.profile patch bug 1077464, the console profiles just listen to the event that a profile started/stopped via console with an optional label, and the perf front starts the profiler, and all other actors necessary. I think we should just have the profiler actor just listen and emit the console events, and make no other assumptions about it, unless there's another downside I'm missing, so that all profiler interaction goes through the performance front.

If we wait to land this in Fx40, the console profile patch should work with the removal of this logic here.

Comment 17

[Victor Porof [:vporof][:vp]]

(In reply to Victor Porof [:vporof][:vp] from comment #13)
> 
> It is not correct to simply count the number of calls to `startProfiler` and
> only actually stop the profiler when this reaches 0 (in `stopProfiler`),
> because `startProfiler` actually discards all the previously recorded data
> (basically throwing away the entire circular buffer). Therefore, we count
> the number of *connections* to the actor, and stop the profiler when all the
> connections close.
> 

This was written under the assumption that the counting to `startProfiler` is done on the instance. However, if we count into a global variable, and the module global scope is always the same for all connections, then this should not be a problem.

After discussing on IRC though, we concluded that it'll be even safer to move this logic on the nsIProfiler side. This will prevent us from accidentally breaking other consumers of the profiler which are not using the actor.

Comment 18

[Shu-yu Guo [:shu]]

Jordan, what do you think I just land this now and leave the console stuff broken until the console patch lands?

Comment 19

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

I really don't want to rebase and reland bug 1077464 a fourth time -- its waiting on checkin needed (feel free to land it) -- that being said, we have many in progress profiler patches that are getting out of sync and out of hand, so if you land bug 1077464 (I'm AFK for a bit) and this passes try, let's land it as well

Comment 20

[Shu-yu Guo [:shu]]

Attachment: Add getElapsedTime to nsIProfiler.

Rebased. Carrying r=mstange.

Comment 21

[Shu-yu Guo [:shu]]

Attachment: In nsProfiler, allow GetProfile and getProfileData to filter by a start time.

Rebased. Carrying r=mstange.

Comment 22

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

So, working on getting this landed. Corrected victor's nits, and reaccessing the console.profile portions. The current patch would not work on correctly matching console.profiles together via the label, and would cause mismatches as the front currently handles that. Changes being implemented:

* console events in profiler server ensure that the profiler is running so we do not lose samples, and send the correct "startTime" for that profile to the front. It no longer handles returning profiler data upon completion. The console.profile functionality is only in the profiler server to provide hooks, and only makes sense within the context of a devtools toolbox, so handling the piecing together of the actual model on the front is OK. Downside is -- there will be a slight delay from receiving the event until actually stopping. This isn't great, but having an "endTime" option filter on getProfileData would fix this, additionally, solve any delay/lag issues between front and server even in just a normal profile. Bug 1155535 for adding "endTime" to getProfileData

* Adding a "traits" property to "getFeatures" for the profiler actor. To contrast with the SPS Profiler "features", "traits" describes features available on the actor, like "filterable" in this case, so we know whether or not to filter samples on the client.

Comment 23

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

Updating console.profileEnd to not actually fetch the samples fixes the issue where samples are fetched twice in console profiles.

Comment 24

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

Attachment: 1145824-filter-samples.patch

Got rid of most test changes -- this shouldn't change the front's interface at all. Added a test for backwards compatibility on older profiler versions. The rest is mentioned well in comment #22.

Comment 25

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

And this is not an objective, measured position, but this FEELS WAY FASTER!!! :D

Comment 26

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

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

Comment 27

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

Comment on attachment 8594145 [details] [diff] [review]
1145824-filter-samples.patch

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

r=me with below addressed

::: toolkit/devtools/server/actors/profiler.js
@@ +55,5 @@
> +      features: nsIProfilerModule.GetFeatures([]),
> +      traits: {
> +        // Whether or not `getProfile()` supports specifying a `startTime`
> +        // and `endTime` to filter out samples.
> +        filterable: true

Why isn't this part of https://dxr.mozilla.org/mozilla-central/source/toolkit/devtools/server/actors/root.js#109-169 ?

The way it is implemented here requires a second RDP round trip, when the frontend could just check the traits that are sent in the server's hello packet and there would be no extra round trip.

Comment 28

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

Comment on attachment 8594145 [details] [diff] [review]
1145824-filter-samples.patch

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

Thanks, Nick! Actually the extra fetch to request the traits causes the perf connection init to be slightly longer, causing a lot of failures due to attempting to destroy perf connection before it's actually created in some tests (that do not have gDevTools.testing on) -- created bug 1155897 for this.

::: toolkit/devtools/server/actors/profiler.js
@@ +55,5 @@
> +      features: nsIProfilerModule.GetFeatures([]),
> +      traits: {
> +        // Whether or not `getProfile()` supports specifying a `startTime`
> +        // and `endTime` to filter out samples.
> +        filterable: true

My thinking was that the root actor has a lot of traits, and this only affects profiler and not something useful on a toolbox level (blackboxing, memory allocations), but you're right, it does require an extra request.

Depending on the future changes to SPS profiler, we may have a few of these little flags, and I just don't want to pollute the global traits for that. Ideally this would be on the ProfilerFront, defined on the server, as a static property, but the profiler is old school.

I'll make this change, but maybe we can change the Profiler to be more in line with our newer actors and clean this up a bit

Comment 29

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

(In reply to Jordan Santell [:jsantell] [@jsantell] from comment #28)
> My thinking was that the root actor has a lot of traits, and this only
> affects profiler and not something useful on a toolbox level (blackboxing,
> memory allocations), but you're right, it does require an extra request.
> 
> Depending on the future changes to SPS profiler, we may have a few of these
> little flags, and I just don't want to pollute the global traits for that.

There are a ton of traits like this -- don't worry about it and just prefix the trait name with "profiler" or something if it makes sense.

> Ideally this would be on the ProfilerFront, defined on the server, as a
> static property, but the profiler is old school.

Unless I misunderstand what you are suggesting, that's not possible. The ProfilerFront is in browser/ and is loaded by frontend code -- the server (in another process) can't define properties on it.

You could define a getter on the ProfilerFront that just checks the hello packet's trait, though. That seems pretty convenient.

Comment 30

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

You're right -- I was thinking about our front's that had static methods (bug 1132208 for example) -- but these are just included on the client via loader, so it'd just get the client's version of traits anyway.

Comment 31

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

Attachment: 1145824-filter-samples.patch

Trying to clean up the tearing down didn't go as planned in bug 1155897 -- most tests do not wait for toolbox to finish being torn down. Readding the gDevTools.testing yield on start up for it to fix it hopefully. Not the cleanest, but it should hopefully work. Added gDevTools.testing to some tests.

Moved profiler trait to root actor.


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

Comment 32

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

Attachment: 1145824-filter-samples.patch

Accidently removed the onGetFeatures method on profiler actor, woops.
https://treeherder.mozilla.org/#/jobs?repo=try&revision=736f8523d1dd

Comment 33

[Shu-yu Guo [:shu]]

Attachment: Add getElapsedTime to nsIProfiler.

Rebased.

Comment 34

[Shu-yu Guo [:shu]]

Attachment: In nsProfiler, allow GetProfile and getProfileData to filter by a start time.

Rebased.

Comment 35

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/5468f1f83ca8
https://hg.mozilla.org/integration/mozilla-inbound/rev/a913dca49e73
https://hg.mozilla.org/integration/mozilla-inbound/rev/20f62a0a4760

Comment 36

[Pulsebot]

https://hg.mozilla.org/integration/fx-team/rev/9bd76ec482d2
https://hg.mozilla.org/integration/fx-team/rev/09b28ebb2216
https://hg.mozilla.org/integration/fx-team/rev/fb84ee59e04a

Comment 37

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

landed on fx-team:
attachment 8597544 [details] [diff] [review]
attachment 8597543 [details] [diff] [review]
attachment 8597438 [details] [diff] [review]

Comment 38

[Pulsebot]

Backout:
https://hg.mozilla.org/integration/mozilla-inbound/rev/fac758428f72
https://hg.mozilla.org/integration/mozilla-inbound/rev/d52486422d8d
https://hg.mozilla.org/integration/mozilla-inbound/rev/255257347998

Comment 39

[Tooru Fujisawa [:arai]]

backed out for mochitest-other failure
https://treeherder.mozilla.org/logviewer.html#?job_id=9295635&repo=mozilla-inbound
https://treeherder.mozilla.org/logviewer.html#?job_id=2829300&repo=fx-team

https://hg.mozilla.org/integration/mozilla-inbound/rev/fac758428f72
https://hg.mozilla.org/integration/mozilla-inbound/rev/d52486422d8d
https://hg.mozilla.org/integration/mozilla-inbound/rev/255257347998

https://hg.mozilla.org/integration/fx-team/rev/08b4fc2d93fd
https://hg.mozilla.org/integration/fx-team/rev/72a3c8f50c17
https://hg.mozilla.org/integration/fx-team/rev/1a0302982302

Comment 40

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

Removing [fixed-in-fx-team]

Shu, if your try tests pass the M-oth failure for just the platform code, let's land it -- reduces the problem area on the front end code.

Comment 41

[Shu-yu Guo [:shu]]

Attachment: Reset dom.send_after_paint_to_content when toggling gDevTools.testing, as chrome tests need it.

Was causing m-oth timeouts.

Comment 42

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

Comment on attachment 8597650 [details] [diff] [review]
Reset dom.send_after_paint_to_content when toggling gDevTools.testing, as chrome tests need it.

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

There were some webide tests running in the mochitest-chrome suite, which had this pref never reset, causing all those lovely failures.

Comment 43

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

Pushed the 2 platform and 2 devtools patches to try with m-oth, in addition to the normal devtools suite: https://treeherder.mozilla.org/#/jobs?repo=try&revision=6449e10ee066

Comment 44

[Pulsebot]

https://hg.mozilla.org/integration/fx-team/rev/5201e29ea4b9
https://hg.mozilla.org/integration/fx-team/rev/a054d84cf08e
https://hg.mozilla.org/integration/fx-team/rev/6349a796bd97
https://hg.mozilla.org/integration/fx-team/rev/4e6cff12b401

Comment 45

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

Round 5
https://hg.mozilla.org/integration/fx-team/rev/5201e29ea4b9
https://hg.mozilla.org/integration/fx-team/rev/a054d84cf08e
https://hg.mozilla.org/integration/fx-team/rev/6349a796bd97
https://hg.mozilla.org/integration/fx-team/rev/4e6cff12b401

Comment 46

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

https://treeherder.mozilla.org/#/jobs?repo=fx-team&revision=4e6cff12b401

Comment 47

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/5201e29ea4b9
https://hg.mozilla.org/mozilla-central/rev/a054d84cf08e
https://hg.mozilla.org/mozilla-central/rev/6349a796bd97
https://hg.mozilla.org/mozilla-central/rev/4e6cff12b401