Closed Bug 1074567 Opened 10 years ago Closed 10 years ago

measure time spent processing in sync CPOW calls per compartment

Categories

(Core :: IPC, defect)

x86
macOS
defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla36
Tracking Status
e10s + ---

People

(Reporter: blassey, Assigned: blassey)

References

Details

Attachments

(1 file, 2 obsolete files)

Attached patch CPOW_Timer.patch (obsolete) — Splinter Review
      No description provided.
Attachment #8497188 - Flags: review?(wmccloskey)
Attachment #8497188 - Flags: review?(bobbyholley)
Comment on attachment 8497188 [details] [diff] [review]
CPOW_Timer.patch

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

I have some style nits, but I'll hold off to make sure Bobby is okay with the design. Bobby, the reason for GetScriptedCaller is that all CPOWs are created in the privileged junk scope, so we can't find the add-on ID from there.

One major problem I just noticed is that the instanceOf and isCallable hooks don't get passed a cx and so we don't account for them. Based on some profiling I did myself over the weekend, these hooks account for the vast majority of the time spent in CPOWs (which is a bug in itself). I'm not sure how to address that without changing the proxy interface.
Since this measures the total amount of time within CPOW calls, how are we going to use the data? If there are many calls but they all take 5-20ms, that's probably much less interesting than a small number of calls that take 50+ms.

As noted in bug 1071880, I'd really like a per-addon histogram, since that will allow us to measure both the number of calls and their impact on jankiness.
Well, the data is already broken down by add-on. I would also like to combine the times of CPOW calls that execute within the same turn of the event loop. So if an add-on does 20 calls that each last 5ms, all from the same event handler, then we would count 100ms in the histogram.
Comment on attachment 8497188 [details] [diff] [review]
CPOW_Timer.patch

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

(In reply to Bill McCloskey (:billm) from comment #1)
> One major problem I just noticed is that the instanceOf and isCallable hooks
> don't get passed a cx and so we don't account for them. Based on some
> profiling I did myself over the weekend, these hooks account for the vast
> majority of the time spent in CPOWs (which is a bug in itself). I'm not sure
> how to address that without changing the proxy interface.

The stack-top cx is always globally inferrable. Just use an AutoJSContext and it'll always be equivalent to taking a cx arg.

::: js/ipc/CPOWTimer.h
@@ +5,5 @@
> +
> +struct JSContext;
> +class JSObject;
> +
> +class CPOWTimer {

Please make this MOZ_STACK_CLASS

@@ +11,5 @@
> +     CPOWTimer(JSObject *obj) : mObj(obj), mStartInterval(PR_IntervalNow()) {}
> +    ~CPOWTimer();
> +private:
> +    JSObject *mObj;
> +    PRIntervalTime mStartInterval;

js style doesn't use mPrefixing.

::: js/ipc/WrapperOwner.cpp
@@ +100,5 @@
>      if (!owner->active()) {                                             \
>          JS_ReportError(cx, "cannot use a CPOW whose process is gone");  \
>          return false;                                                   \
> +    } else {                                                            \
> +        CPOWTimer timer(JS::GetScriptedCallerGlobal(cx));               \

Hm. So relying on the scripted caller here is pretty hacky, and won't do the right thing in various edge cases. The right thing to do here is to use a custom wrapper subclass for accessing CPOWs, and add the necessary instrumentation at that layer. But that's a bit of a pain, and given that this is just for telemetry I'm fine to just do the expedient thing here.

We should definitely use mozilla::dom::GetIncumbentGlobal here, because that will at least do a better job of handling some of the edge cases. For example, if the addon does setTimeout(someCPOWedFunction, ...), the incumbent global will still be the addon global whereas the scripted caller global will be null.

So please add that, and add a comment here explaining that this is a best-effort sort of thing.

::: js/xpconnect/src/xpcprivate.h
@@ +3696,4 @@
>      // XPConnect compartment.
>      XPCWrappedNativeScope *scope;
>  
> +    // A running count of how much time we've spent processing CPOWs

Nit - add a period, and put this member immediately after warnedAboutXrays.
Attachment #8497188 - Flags: review?(bobbyholley) → review+
Assignee: nobody → blassey.bugs
Comment on attachment 8497188 [details] [diff] [review]
CPOW_Timer.patch

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

You'll need to put a license and the emacs/vi modelines in CPOWTimer.{cpp,h}.

::: js/ipc/CPOWTimer.cpp
@@ +1,5 @@
> +#include "CPOWTimer.h"
> +#include "jsfriendapi.h"
> +#include "xpcprivate.h"
> +
> +CPOWTimer::~CPOWTimer() {

Brace goes on its own line.

@@ +2,5 @@
> +#include "jsfriendapi.h"
> +#include "xpcprivate.h"
> +
> +CPOWTimer::~CPOWTimer() {
> +  PRIntervalTime time = PR_IntervalNow() - mStartInterval;

Four space indent within js/.

::: js/ipc/CPOWTimer.h
@@ +6,5 @@
> +struct JSContext;
> +class JSObject;
> +
> +class CPOWTimer {
> + public:

public: should be indented two spaces.

@@ +7,5 @@
> +class JSObject;
> +
> +class CPOWTimer {
> + public:
> +     CPOWTimer(JSObject *obj) : mObj(obj), mStartInterval(PR_IntervalNow()) {}

This should be indented 4 spaces, not 5.

@@ +9,5 @@
> +class CPOWTimer {
> + public:
> +     CPOWTimer(JSObject *obj) : mObj(obj), mStartInterval(PR_IntervalNow()) {}
> +    ~CPOWTimer();
> +private:

Also two-space indent.
Attachment #8497188 - Flags: review?(wmccloskey) → review+
my push failed the hazards test. As a note to myself, I need "try: -b do -p linux64-br-haz -u none" on a try push to test it
(In reply to Brad Lassey [:blassey] (use needinfo?) from comment #6)
> my push failed the hazards test. As a note to myself, I need "try: -b do -p
> linux64-br-haz -u none" on a try push to test it

correction "try: -b do -p linux64-b2g-haz -u none"
Attached patch CPOW_Timer.patch (obsolete) — Splinter Review
Asking for re-review since I had to change this to get try to run green.

Try run: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=6796e2d634d4
Attachment #8497188 - Attachment is obsolete: true
Attachment #8525464 - Flags: review?(wmccloskey)
Attached patch CPOW_Timer.patchSplinter Review
moved the comment
Attachment #8525464 - Attachment is obsolete: true
Attachment #8525464 - Flags: review?(wmccloskey)
Attachment #8525472 - Flags: review?(wmccloskey)
Attachment #8525472 - Flags: review?(bobbyholley)
Comment on attachment 8525472 [details] [diff] [review]
CPOW_Timer.patch

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

::: js/ipc/WrapperOwner.cpp
@@ +132,5 @@
>      WrapperOwner *owner = OwnerOf(proxy);                               \
>      if (!owner->active()) {                                             \
>          JS_ReportError(cx, "cannot use a CPOW whose process is gone");  \
>          return false;                                                   \
> +    } else {                                                            \

Nit - Remove the else and just make it a scoped block.
Attachment #8525472 - Flags: review?(wmccloskey)
Attachment #8525472 - Flags: review?(bobbyholley)
Attachment #8525472 - Flags: review+
Comment on attachment 8525472 [details] [diff] [review]
CPOW_Timer.patch

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

::: js/ipc/CPOWTimer.cpp
@@ +8,5 @@
> +#include "jsfriendapi.h"
> +#include "xpcprivate.h"
> +#include "CPOWTimer.h"
> +
> +CPOWTimer::~CPOWTimer() {

Also, this brace should go on its own line.
https://hg.mozilla.org/mozilla-central/rev/dc5206885f87
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla36
You need to log in before you can comment on or make changes to this bug.