Closed Bug 1479740 Opened 6 years ago Closed 6 years ago

Track Web API calls made in the child

Categories

(Toolkit :: Performance Monitoring, enhancement)

Product:
Toolkit
Component:
Performance Monitoring
Type:
enhancement
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla64
Tracking Flags:
Tracking Status
firefox64 --- fixed

People

(Reporter: tarek, Assigned: tarek)

References

Details

Attachments

(3 files)

Bug 1479740 - Track Web API calls made in the child -
59 bytes, text/x-review-board-request
Details
Original patch
18.51 KB, patch
Details | Diff | Splinter Review
Bug 1479740 - Track Web API calls made in the child - r?mixedpuppy,florian
46 bytes, text/x-phabricator-request
florian
: review+
mixedpuppy
: review+
Details | Review 
Let's extend the performance counters so API calls made in the children are also accounted for
Assignee: nobody → tarek
Comment on attachment 8996269 [details]
Bug 1479740 - Track Web API calls made in the child -

https://reviewboard.mozilla.org/r/260444/#review267506


Code analysis found 4 defects in this patch:
 - 4 defects found by mozlint

You can run this analysis locally with:
 - `./mach lint path/to/file` (JS/Python)


If you see a problem in this automated review, please report it here: http://bit.ly/2y9N9Vx


::: toolkit/components/extensions/ExtensionChild.jsm:57
(Diff revision 1)
>    EventEmitter,
>    EventManager,
>    LocalAPIImplementation,
>    LocaleData,
>    NoCloneSpreadArgs,
> +  retrievePerformanceCounters,

Error: 'retrievePerformanceCounters' is assigned a value but never used. Allowed unused vars must match /^console$/. [eslint: no-unused-vars]

::: toolkit/components/extensions/ExtensionChild.jsm:968
(Diff revision 1)
> +
> +      case "API:RetrievePerformanceCounter":
> +        return new Promise(resolve => {
> +          resolve(ExtensionCommon.retrievePerformanceCounters());
> +        });
> +        break;

Error: Unreachable code. [eslint: no-unreachable]

::: toolkit/components/extensions/ExtensionParent.jsm:898
(Diff revision 1)
> +    // ask all children to send back their counters
> +    for (let [childId, context] of this.proxyContexts) {
> +      let recipient = {childId};
> +      let data = {"childId": childId};
> +      let res = await context.sendMessage(context.parentMessageManager,
> +                  "API:RetrievePerformanceCounter", data, {recipient});

Error: Expected indentation of 42 spaces but found 18. [eslint: indent]

::: toolkit/components/extensions/ExtensionParent.jsm:904
(Diff revision 1)
> +      for (let [webextId, counters] of res) {
> +        for (let [api, counter] of counters) {
> +          let current = result.get(webextId).get(api);
> +          current.calls += counter.calls;
> +          current.duration += counter.duration;
> +          }

Error: Expected indentation of 8 spaces but found 10. [eslint: indent]
Comment on attachment 8996269 [details]
Bug 1479740 - Track Web API calls made in the child -

https://reviewboard.mozilla.org/r/260444/#review267508


Code analysis found 7 defects in this patch:
 - 7 defects found by mozlint

You can run this analysis locally with:
 - `./mach lint path/to/file` (JS/Python)


If you see a problem in this automated review, please report it here: http://bit.ly/2y9N9Vx


::: toolkit/components/extensions/ExtensionChild.jsm:57
(Diff revision 2)
>    EventEmitter,
>    EventManager,
>    LocalAPIImplementation,
>    LocaleData,
>    NoCloneSpreadArgs,
> +  retrievePerformanceCounters,

Error: 'retrievePerformanceCounters' is assigned a value but never used. Allowed unused vars must match /^console$/. [eslint: no-unused-vars]

::: toolkit/components/extensions/ExtensionChild.jsm:969
(Diff revision 2)
> +
> +      case "API:RetrievePerformanceCounter":
> +        return new Promise(resolve => {
> +          resolve(ExtensionCommon.retrievePerformanceCounters());
> +        });
> +        break;

Error: Unreachable code. [eslint: no-unreachable]

::: toolkit/components/extensions/ExtensionParent.jsm:48
(Diff revision 2)
>    BaseContext,
>    CanOfAPIs,
>    SchemaAPIManager,
>    SpreadArgs,
>    defineLazyGetter,
> +  storeExecutionTime,

Error: 'storeExecutionTime' is assigned a value but never used. Allowed unused vars must match /^console$/. [eslint: no-unused-vars]

::: toolkit/components/extensions/ExtensionParent.jsm:49
(Diff revision 2)
>    CanOfAPIs,
>    SchemaAPIManager,
>    SpreadArgs,
>    defineLazyGetter,
> +  storeExecutionTime,
> +  retrievePerformanceCounters

Error: 'retrievePerformanceCounters' is assigned a value but never used. Allowed unused vars must match /^console$/. [eslint: no-unused-vars]

::: toolkit/components/extensions/ExtensionParent.jsm:49
(Diff revision 2)
>    CanOfAPIs,
>    SchemaAPIManager,
>    SpreadArgs,
>    defineLazyGetter,
> +  storeExecutionTime,
> +  retrievePerformanceCounters

Error: Missing trailing comma. [eslint: comma-dangle]

::: toolkit/components/extensions/ExtensionParent.jsm:891
(Diff revision 2)
> -    apiCounter.calls += 1;
> +    // ask all children to send back their counters
> +    for (let [childId, context] of this.proxyContexts) {
> +      let recipient = {childId};
> +      let data = {"childId": childId};
> +      let res = await context.sendMessage(context.parentMessageManager,
> +                  "API:RetrievePerformanceCounter", data, {recipient});

Error: Expected indentation of 42 spaces but found 18. [eslint: indent]

::: toolkit/components/extensions/ExtensionParent.jsm:897
(Diff revision 2)
> +      for (let [webextId, counters] of res) {
> +        for (let [api, counter] of counters) {
> +          let current = result.get(webextId).get(api);
> +          current.calls += counter.calls;
> +          current.duration += counter.duration;
> +          }

Error: Expected indentation of 8 spaces but found 10. [eslint: indent]
Comment on attachment 8996269 [details]
Bug 1479740 - Track Web API calls made in the child -

https://reviewboard.mozilla.org/r/260444/#review268112

We already discussed the othe changes this requires on IRC.

::: toolkit/components/extensions/ExtensionCommon.jsm:879
(Diff revision 3)
>    constructor(pathObj, name, context) {
>      super();
>      this.pathObj = pathObj;
>      this.name = name;
>      this.context = context;
> +    XPCOMUtils.defineLazyPreferenceGetter(this, "_timingEnabled", TIMING_ENABLED_PREF, false);

This should be a single global getter than one per instance.
Attachment #8996269 - Flags: review?(kmaglione+bmo)
Comment on attachment 8996269 [details]
Bug 1479740 - Track Web API calls made in the child -

https://reviewboard.mozilla.org/r/260444/#review268308


Code analysis found 1 defect in this patch:
 - 1 defect found by mozlint

You can run this analysis locally with:
 - `./mach lint path/to/file` (JS/Python/etc)


If you see a problem in this automated review, please report it here: http://bit.ly/2y9N9Vx


::: toolkit/components/extensions/test/xpcshell/test_ext_performance_counters.js:18
(Diff revision 4)
> +
>  async function test_counter() {
>    async function background() {
> -    // creating a bookmark
> +
> +    function sleep(time) {
> +      return new Promise((resolve) => setTimeout(resolve, time));

Error: Listen for events instead of setTimeout() with arbitrary delay [eslint: mozilla/no-arbitrary-setTimeout]
Comment on attachment 8996269 [details]
Bug 1479740 - Track Web API calls made in the child -

https://reviewboard.mozilla.org/r/260444/#review268450

This looks much better. Thanks.

My main issue at this point is that I think we should use DeferredTask.jsm to handle the flushing. See comments. Sorry I didn't think to suggest it earlier.

::: modules/libpref/init/all.js:4997
(Diff revision 5)
>  pref("extensions.webextensions.ExtensionStorageIDB.enabled", false);
>  
>  // if enabled, store execution times for API calls
>  pref("extensions.webextensions.enablePerformanceCounters", false);
>  
> +// Maximum age in seconds of performance counters in children

We typically store all time values in milliseconds. Please do the same here, unless you have a specific reason to do otherwise.

::: toolkit/components/extensions/ExtensionChild.jsm:865
(Diff revision 5)
>    }
>  }
>  
> +
> +class ChildLocalAPIImplementation extends LocalAPIImplementation {
> +  constructor(pathObj, name, childApiManager, maxAge) {

The `maxAge` argument appears to be unused.

::: toolkit/components/extensions/ExtensionChild.jsm:868
(Diff revision 5)
> +    XPCOMUtils.defineLazyPreferenceGetter(this, "_timingEnabled", TIMING_ENABLED_PREF, false);
> +    XPCOMUtils.defineLazyPreferenceGetter(this, "_maxAge", TIMING_MAX_AGE, 0);

Again, please define these globally rather than on an instance.

::: toolkit/components/extensions/ExtensionChild.jsm:882
(Diff revision 5)
> +      if (age > this._maxAge) {
> +        ChromeUtils.idleDispatch(() => {
> +          let options = {childId: this.childApiManager.id,
> +                         counters: PerformanceCounters.retrievePerformanceCounters(true)};
> +          this.childApiManager.messageManager.sendAsyncMessage("API:SendPerformanceCounter",
> +                                                               options);
> +        }, {timeout: 1});
> +      }
> +    }

We typically use [DeferredTask](https://searchfox.org/mozilla-central/source/toolkit/modules/DeferredTask.jsm) for this kind of thing. As a bonus, it handles the idle dispatch part automatically.

::: toolkit/components/extensions/ExtensionCommon.jsm:48
(Diff revision 5)
>    getInnerWindowID,
>    getUniqueId,
>    getWinUtils,
>  } = ExtensionUtils;
>  
> +

Nit: Unrelated whitespace change.

::: toolkit/components/extensions/ExtensionCommon.jsm
(Diff revision 5)
>    makeWidgetId,
>    normalizeTime,
>    runSafeSyncWithoutClone,
>    stylesheetMap,
>    withHandlingUserInput,
> -

Unrelated whitespace change.

::: toolkit/components/extensions/ExtensionParent.jsm:41
(Diff revision 5)
>    aomStartup: ["@mozilla.org/addons/addon-manager-startup;1", "amIAddonManagerStartup"],
>  });
>  
>  ChromeUtils.import("resource://gre/modules/ExtensionCommon.jsm");
>  ChromeUtils.import("resource://gre/modules/ExtensionUtils.jsm");
> +ChromeUtils.import("resource://gre/modules/PerformanceCounters.jsm");

Please add this to the lazy getter list above.

::: toolkit/components/extensions/PerformanceCounters.jsm:34
(Diff revision 5)
> + * Returns the performance counters.
> + *
> + * @param {boolean} purge Whether we empty the counters or not
> + * @returns {DefaultMap}
> + */
> +function retrievePerformanceCounters(purge) {

I'd rather this be called something like `flushPerformanceCounters` and the side-effect-free version have a different name (`getPerformanceCounters`?) rather than just take a boolean argument.

::: toolkit/components/extensions/PerformanceCounters.jsm:56
(Diff revision 5)
> +/**
> + * Merges an PerformanceCounter map into the global one.
> + * Can be used by the main process to merge data received
> + * from the children.
> + *
> + * @param {DefaultMap} data the map to merge

Nit: Please capitalize the first word of sentences. Same elsewhere.

::: toolkit/components/extensions/PerformanceCounters.jsm:57
(Diff revision 5)
> + * Merges an PerformanceCounter map into the global one.
> + * Can be used by the main process to merge data received
> + * from the children.
> + *
> + * @param {DefaultMap} data the map to merge
> + * @returns {undefined}

Nit: No need for @returns

::: toolkit/components/extensions/PerformanceCounters.jsm:76
(Diff revision 5)
> + *
> + * @param {string} webExtensionId the web extension id
> + * @param {string} apiPath the API path
> + * @param {integer} duration how long the call took
> + *
> + * When context is provided, a call to API:SendPerformanceCounter is done.

Nit: Please move above params.

::: toolkit/components/extensions/PerformanceCounters.jsm:78
(Diff revision 5)
> + * @param {string} apiPath the API path
> + * @param {integer} duration how long the call took
> + *
> + * When context is provided, a call to API:SendPerformanceCounter is done.
> + *
> + * @returns {integer} how old the counters data is in seconds since the last purge

We typically store all times in milliseconds. Please do the same here, unless you have a specific reason to do otherwise.

::: toolkit/components/extensions/PerformanceCounters.jsm:84
(Diff revision 5)
> + */
> +function storeExecutionTime(webExtensionId, apiPath, duration) {
> +  let apiCounter = performanceCounters.get(webExtensionId).get(apiPath);
> +  apiCounter.duration += duration;
> +  apiCounter.calls += 1;
> +  return Math.floor((new Date().getTime() - purgeTime) / 1000);

Please use `Date.now()` or `Cu.now()` rather than `new Date`. Constructing Date objects is expensive.

Same above.

That said, we're probably better off just using DeferredTask rather than having this return a timestamp.

::: toolkit/components/extensions/PerformanceCounters.jsm:88
(Diff revision 5)
> +  retrievePerformanceCounters,
> +  storeExecutionTime,
> +  mergePerformanceCounters

Nit: Please sort properties.

::: toolkit/components/extensions/test/xpcshell/test_ext_performance_counters.js:15
(Diff revision 5)
>  } = ExtensionParent;
>  
> -
>  async function test_counter() {
>    async function background() {
> -    // creating a bookmark
> +    function sleep(time) {

We typically call this `delay` or `promiseDelay`. Sleep implies that the thread is frozen, which is not the case here.
Attachment #8996269 - Flags: review?(kmaglione+bmo)
Comment on attachment 8996269 [details]
Bug 1479740 - Track Web API calls made in the child -

https://reviewboard.mozilla.org/r/260444/#review269378

::: toolkit/components/extensions/ExtensionChild.jsm:43
(Diff revision 6)
>    () => Cc["@mozilla.org/webextensions/extension-process-script;1"]
>            .getService().wrappedJSObject);
>  
>  ChromeUtils.import("resource://gre/modules/ExtensionCommon.jsm");
>  ChromeUtils.import("resource://gre/modules/ExtensionUtils.jsm");
> +ChromeUtils.import("resource://gre/modules/PerformanceCounters.jsm");

Please make this a lazy import.

::: toolkit/components/extensions/ExtensionChild.jsm:881
(Diff revision 6)
> +        this._purger = new DeferredTask(() => {
> +          if (!this.childApiManager.context.active) {
> +            return;
> +          }
> +          let options = {childId: this.childApiManager.id,
> +                         counters: PerformanceCounters.flushPerformanceCounters()};
> +          this.childApiManager.messageManager.sendAsyncMessage("API:SendPerformanceCounter",
> +                                                               options);
> +          // Re-arm the Deferred Task
> +          this._purger.arm();
> +        }, PerformanceCounters.getTimingMaxAge());

There should be one global task. You should call .arm() every time it changes. You should *not* call .arm() from the callback.

::: toolkit/components/extensions/ExtensionChild.jsm:887
(Diff revision 6)
> +          this.childApiManager.messageManager.sendAsyncMessage("API:SendPerformanceCounter",
> +                                                               options);

Please just send this via Services.cpmm, and add a single listener on ppmm on the parent side.

::: toolkit/components/extensions/PerformanceCounters.jsm:22
(Diff revision 6)
> +
> +const {
> +  DefaultMap,
> +} = ExtensionUtils;
> +
> +XPCOMUtils.defineLazyPreferenceGetter(this, "gTimingEnabled", "extensions.webextensions.enablePerformanceCounters", false);

Nit: These lines are very long. Please add newlines after the second and third arguments.

::: toolkit/components/extensions/PerformanceCounters.jsm:25
(Diff revision 6)
> +function _initializeCounters() {
> +  return new DefaultMap(() => new DefaultMap(() => ({duration: 0, calls: 0})));
> +}

`_initializeCounters` is kind of a weird way to name this.

Maybe make it something like:

    class CounterMap extends DefaultMap {
      defaultConstructor() {
        return new DefaultMap(() => ({duration: 0, calls: 0}));
      }
    }

::: toolkit/components/extensions/PerformanceCounters.jsm:32
(Diff revision 6)
> + * Returns true if performance counters are enabled.
> + *
> + * Indirection used so gTimingEnabled is not exposed direcly
> + * in PerformanceCounters -- which would prevent tests to dynamically
> + * change the preference value once PerformanceCounters.jsm is loaded.
> + *
> + * @returns {boolean}
> + */
> +function isPerformanceCountersEnabled() {
> +  return gTimingEnabled;
> +}

Please just make this a getter on the PerformanceCounters object:

    get enabled() { return gTimingEnabled; }

::: toolkit/components/extensions/PerformanceCounters.jsm:44
(Diff revision 6)
> +/**
> + * Returns the counters max age
> + *
> + * Indirection used so gTimingMaxAge is not exposed direcly
> + * in PerformanceCounters -- which would prevent tests to dynamically
> + * change the preference value once PerformanceCounters.jsm is loaded.
> + *
> + * @returns {number}
> + */
> +function getTimingMaxAge() {
> +  return gTimingMaxAge;
> +}
> +
> +/**
> + * Returns the performance counters.
> + *
> + * @returns {DefaultMap}
> + */
> +function retrievePerformanceCounters() {
> +  return performanceCounters;
> +}

Same here. Please just make these getters.

::: toolkit/components/extensions/test/xpcshell/test_ext_performance_counters.js:30
(Diff revision 6)
> +    browser.extension.getURL("beasts/frog.html");
> +    browser.extension.getURL("beasts/frog2.html");
> +    browser.extension.getURL("beasts/frog3.html");
> +
> +    // wait two seconds so the child sends back its counters
> +    await promiseDelay(2000);

This is kind of racy... We should really just wait for the message from the child...
Attachment #8996269 - Flags: review?(kmaglione+bmo)
Comment on attachment 8996269 [details]
Bug 1479740 - Track Web API calls made in the child -

https://reviewboard.mozilla.org/r/260444/#review269686

::: toolkit/components/extensions/ExtensionChild.jsm:886
(Diff revision 7)
> +      // If we store a performance counter for the first time, we create this._purger.
> +      // If this._purger already exists and is not armed, we arm it.
> +      if (!this._purger) {
> +        this._purger = new DeferredTask(() => {
> +          this.sendPerformanceCounter();
> +        }, PerformanceCounters.maxAge);
> +        this._purger.arm();
> +      } else if (!this._purger.isArmed) {
> +        this._purger.arm();
> +      }

Sorry, but there really does need to be only a sinble global DeferredTask for this. We create one of these instances for every API method in every extension document or content script. The extra overhead will add up fast.

::: toolkit/components/extensions/ExtensionChild.jsm:893
(Diff revision 7)
> +      if (!this._purger) {
> +        this._purger = new DeferredTask(() => {
> +          this.sendPerformanceCounter();
> +        }, PerformanceCounters.maxAge);
> +        this._purger.arm();
> +      } else if (!this._purger.isArmed) {

There's no need to check isArmed.

::: toolkit/components/extensions/ExtensionParent.jsm:510
(Diff revision 7)
>        apiManager.on("extension-browser-inserted", this._onExtensionBrowser);
>        this.initialized = true;
>      }
>  
>      this.extensionMap.set(extension.id, extension);
> +    Services.ppmm.addMessageListener("Extension:SendPerformanceCounter", this);

This needs to be in the `extensionMap.size == 0` if.

::: toolkit/components/extensions/ExtensionParent.jsm:514
(Diff revision 7)
>      this.extensionMap.set(extension.id, extension);
> +    Services.ppmm.addMessageListener("Extension:SendPerformanceCounter", this);
>    },
>  
>    uninit(extension) {
> +    Services.ppmm.removeMessageListener("Extension:SendPerformanceCounter", this);

This likewise needs to be in the `if` below.

::: toolkit/components/extensions/test/xpcshell/test_ext_performance_counters.js:7
(Diff revision 7)
>  /* vim: set sts=2 sw=2 et tw=80: */
>  "use strict";
>  
>  ChromeUtils.import("resource://gre/modules/ExtensionParent.jsm");
> +ChromeUtils.import("resource://gre/modules/PerformanceCounters.jsm");
> +ChromeUtils.import("resource://gre/modules/Promise.jsm");

Please don't use Promise.jsm. We're trying to get rid of it.
Attachment #8996269 - Flags: review?(kmaglione+bmo)
Thanks for the review

> Sorry, but there really does need to be only a sinble global DeferredTask for this.

I am confused at the memory model then. I made the assumption we had a single instance of that class per thread,
should I move the deferred task as a global variable, or is there a preferred location to add it ? Thanks!
Flags: needinfo?(kmaglione+bmo)
Attached patch Original patch — — Splinter Review 
I am attaching the patch here since it was lost from reviewboard...
The performance counter is now also used in the children, and
the ParentAPIManager.retrievePerformanceCounters() can be used
to aggregate all counters into a promise.
Attachment #9007701 - Attachment description: Bug 1479740 - Track Web API calls made in the child - r?kmag → Bug 1479740 - Track Web API calls made in the child - r?mixedpuppy,florian
Flags: needinfo?(kmaglione+bmo)
Comment on attachment 9007701 [details]
Bug 1479740 - Track Web API calls made in the child - r?mixedpuppy,florian

Florian Quèze [:florian] has approved the revision.
Attachment #9007701 - Flags: review+
Comment on attachment 9007701 [details]
Bug 1479740 - Track Web API calls made in the child - r?mixedpuppy,florian

Shane Caraveo (:mixedpuppy) has approved the revision.
Attachment #9007701 - Flags: review+
Pushed by tziade@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/09b97f54eed8
Track Web API calls made in the child - r=florian,mixedpuppy
https://hg.mozilla.org/mozilla-central/rev/09b97f54eed8
Status: NEW → RESOLVED
Closed: 6 years ago
status-firefox64: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla64
Depends on: 1571077
Regressions: 1736816
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: