Shaver: in http://groups.google.com/group/mozilla.dev.platform/msg/2e712f13029e2c18?pli=1, you said you had some prototype code for doing per-compartment CPU accounting. Can you dig it up? It seems like a really good idea for identifying performance problems, and it would be a waste to lose it.

I have it on a computer that is still not reassembled from the move, but it was pretty simple. I think I gave it to billm, possibly, but it was just some counters in the compartment, some flags for whether we were counting, and a bit of ugly in CrossCompartmentCall to suspend one counter and use the other. I don't think I got it right, but you probably will. :-) It used rdtsc, so it probably sucked there in terms of accuracy. It had counters for gc/execution/compilation, but I only wired up the execution and compilation ones at the time (compartment GC was still learning to walk). I can boot the machine this weekend and look for it, but I think you are overestimating the amount of work it would take to reconstruct.

This was the patch shaver sent me a while ago. I incorporated some of it into bug 604761, although not the compartment stuff (which seems like what you want).

Comment on attachment 548990 [details] [diff] [review] shaver's patch Review of attachment 548990 [details] [diff] [review]: ----------------------------------------------------------------- ::: js/src/jsaccounting.h @@ +43,5 @@ > +#include "nanojit/avmplus.h" > +#include "jswin.h" > + > +/* don't conflict with nanojit's version */ > +#if !defined(AVMPLUS_HAS_RDTSC) Getting this to work where nanojit was involved and where it wasn't (depending on include order) was a nightmare. It probably ended up 3x as complicated as it needed to be. @@ +148,5 @@ > + void reset() { accumulated = 0; startTicks = 0; }; > + > + uint64 ticks() { return accumulated; } > + > + double megaticks() { return double(accumulated) / 1e6; } This method name is the only thing I insist that you keep. ::: js/src/jswin.h @@ +46,1 @@ > #endif I don't know why I needed to make this change, but I bet I was FURIOUS at the time.

(The latter comment refers to the "#undef CONST" in there -- dunno why it didn't show up in the stanza.)

I have a bit of work from bug 639085 that might be useful here. In the bug, I wanted to measure the percent of non-blocked main-thread browser time in various parts of JS/XPConnect (to see if I wanted to work on a certain optimization project). The patch started as a simple keep-a-running-rdtsc-sum-and-print-at-program-end quick hack. What I found is that, to get useful data (viz., blame cpu time on the real offender and not just the innermost enclosing measurement point), you need to have a wee bit of logic (you can see this in jstimelog.h and the analysis). I found the only reasonable way to do this was by spewing a log and analyzing it after the fact (much like TraceVis). Example output is attachment 519497 [details] (cryptic output is explained by the README file in the patch, which is derived from hg.mozilla.org/users/lwagner_mozilla.com/measure). Keeping a log does incur non-trivial overhead. Taras pointed out that we should be able to land this without perf regression by using dtrace-style hooks. Thinking about about:cpu (or whatever it gets called), one possible UI would be to have a "start" button that inserts the hooks and starts the log, and a "stop" button that takes out the hooks, analyzes the log and prints the results on the page. Another idea (that is implemented in the patch via the "Cutoff" column) is to have the analysis only include data for time intervals where the total interval between starting and finishing the event (from the event queue) is greater than X ms (for multiple values of X). This answers the question: who was responsible for making my browser hang just then (kinda like Shark's WTF mode). Hope this is useful; glad to see this bug!

I'll try and work on this during this quarter.

Note that my objective is slightly different. I wish to feed the data to Telemetry in a first time so: - no special UX for turning this on/off (perhaps a preference); - we should make this as fast as possible. If we find out that there is no way to make this fast, we may wish to activate the accounting only if the user is facing actual jank, and only long enough to take a sample. As a side-note, I read that `rdtsc` is not recommended and we should rather use `GetPerformanceCounter` under Windows, `clock_gettime` under Linux, and I'm not sure what (`getrusage`, maybe?) under MacOS X.

QueryPerformanceCounter is the thing to use on Windows (depending on your needs, we may have some existing wrappers that keep it synchronized with the system clock), but note that it can be slow on some older systems, especially on Windows XP. I don't think there's anything better though - it should already use rdtsc or the HPET under the hood when available.

I just ran a quick test. Adding `getrusage` at every single call to `setCompartment` appears to incur a 2% penalty on general browsing on Mac OS X, according to Instruments. The total overhead would probably be a bit higher, as we need to actually do something with the data’. If we only do this in case of jank, that might be an acceptable cost. Vladan, is that compatible with what you have in mind?

According to npb, this manner of measuring causes us to call `getrusage` every time a compartment accesses data from another compartment, which seems way over the top. I have moved the measurement to probes::{EnterScript, ExitScript, StartExecution, StopExecution}, and, in regular browsing, this seems to lower the overhead of `getrusage` to 0.7-0.8%.

*EXCELLENT*

For starters, how about we keep the instrumentation on at all times, but only enable the feature on Nightly

> I wish to feed the data to Telemetry Why? We have some memory measurements reported via telemetry, but they are of limited use and I only look at them occasionally. In comparison, about:memory is extremely useful for investigating individual sessions. I suspect per-compartment CPU accounting would be similar -- great when a single user has bad performance, but of little use in aggregate. Plus you can't report content URLs without violating user privacy...

Vladan: Ok, that sounds good. Next step is determining what I can do with the data. njn: The idea is to spot both websites and add-ons that hurt us, so that we can then investigate with the profiler at hand. However, I have filed bug 1118944 for an about:cpu. The issue of user privacy definitely needs to be discussed. Vladan?

Yup, we can't report domains or URLs to Telemetry. I listed the uses for this feature here: https://bugzilla.mozilla.org/show_bug.cgi?id=1119255#c2 Let's have the discussion there?

Note that we could use sampling if the overhead of doing this per enter/exit is too high. But if its not then instrumentation would be much simpler.

After discussing with blassey, we realized that 1/ we are both working on the same topic, with different strategies, 2/ neither of us was measuring the right data. Here is an early prototype, with a few tweaks on both our strategies. It measures: - only when we are crossing compartments to execute code (rather than whenever we cross compartments to access data); - only for the topmost meaningful compartment (i.e. the highest compartment on the stack that is either a webpage or an add-on); - both raw CPU cost and actual jank. With my usual benchmarks, we are now down to a 0.3% performance impact.

Two questions: 1) Do webpages have a non-null addonId? Otherwise this seems like it would only measure time spent in add-on compartments. 2) Could an add-on install something on content script that would cause said script's compartment to enter the add-on compartment and spend a significant amount of time there? If so, do we really want all that time to be attributed to the topmost compartment?

1) I don't understand your question. I think that webpages have a null addonId and have `isSystem` set to false, so we should measure time spent in them. Did I get my code wrong? 2) I assume you mean web content, and not e10s content script, right? If so, I'm sure that this can happen, although I'm not sure how often. I guess we could allow nested timewatches in such cases. This would probably complicate the code a little, but probably not by much.

(In reply to David Rajchenbach-Teller [:Yoric] (hard to reach until January 10th - use "needinfo") from comment #21) > 1) I don't understand your question. I think that webpages have a null > addonId and have `isSystem` set to false, so we should measure time spent in > them. Did I get my code wrong? Sorry, I shouldn't read code when I'm tired. I was looking at code your patch *removed*.

Looks like you still need to handle nested event loops somehow, to avoid counting idle time against a compartment.

Comment on attachment 8546925 [details] [diff] [review] Per compartment CPU accounting Review of attachment 8546925 [details] [diff] [review]: ----------------------------------------------------------------- ::: js/src/vm/Interpreter.cpp @@ +429,5 @@ > + > + const JSCompartment* compartment = cx->compartment(); > + if (compartment->isSystem && !compartment->addonId) { > + // This frame is part of Firefox itself, don't > + // monitor it. why not monitor chrome scripts? @@ +436,5 @@ > + > + if (sIsRunning.get()) { > + // We are already running a stopwatch on this thread. > + // Let's not run two stopwatches at the same time, as > + // it's slow and just makes things more confusing. this is the discussion we were having on #developers. If compartment A calls into compartment B, this will allocate all of that time spent to compartment B. The patch I landed double counts that time to both A and B. I can think of instances where both (or the third option of only allocating the time spent in B to B) would be useful

Profilers since time immemorial have supported both function-and-all-children and only-function-proper reporting because there are many such instances. (A-but-only-when-called-from-B is usually an arcane post-processing step.)

(In reply to Brad Lassey [:blassey] (use needinfo?) from comment #24) > ::: js/src/vm/Interpreter.cpp > @@ +429,5 @@ > > + > > + const JSCompartment* compartment = cx->compartment(); > > + if (compartment->isSystem && !compartment->addonId) { > > + // This frame is part of Firefox itself, don't > > + // monitor it. > > why not monitor chrome scripts? Well, I would like to start with something reasonably simple and fast. I suspect that attempting to monitor several nested compartments simultaneously will both complicate things and slow them down. Also, I may be wrong, but I suspect that there will be some chrome code running higher on the stack than most/all add-on code. > > @@ +436,5 @@ > > + > > + if (sIsRunning.get()) { > > + // We are already running a stopwatch on this thread. > > + // Let's not run two stopwatches at the same time, as > > + // it's slow and just makes things more confusing. > > this is the discussion we were having on #developers. If compartment A calls > into compartment B, this will allocate all of that time spent to compartment > B. The patch I landed double counts that time to both A and B. I can think > of instances where both (or the third option of only allocating the time > spent in B to B) would be useful Unless I'm writing my code wrong, I am counting that time to A. If I recall our conversation on #developers, I was advocating counting the time to both A and B, until you remarked that this would cause double-counts if both A and B were in the same add-on/tab/etc. I believe that just having the information on A will already be an improvement, and that we can refine later with more experience. Does this sound ok to you or are you aware of some data that we could use immediately and that I'm missing? (In reply to Mike Shaver (:shaver -- probably not reading bugmail closely) from comment #25) > Profilers since time immemorial have supported both > function-and-all-children and only-function-proper reporting because there > are many such instances. (A-but-only-when-called-from-B is usually an arcane > post-processing step.) Indeed. I just hope that we can get away with not writing an entire profiler immediately.

Comment on attachment 8546925 [details] [diff] [review] Per compartment CPU accounting Review of attachment 8546925 [details] [diff] [review]: ----------------------------------------------------------------- Sorry for the delay. For some reason I often miss the feedback requests when I look at the queue. Seems reasonable at a quick glance. sfink mentioned nested event loops, do you want to handle those somewhere? Some nits below, I assume error handling etc will be fixed up before review. ::: js/src/jscompartment.h @@ +169,5 @@ > unsigned enterCompartmentDepth; > int64_t startInterval; > > public: > + struct Performance { Nice idea to group these in a struct. ::: js/src/vm/Interpreter.cpp @@ +420,5 @@ > + * Implementation of per-compartment performance measurement. > + */ > +struct JSAutoStopWatch MOZ_FINAL > +{ > + inline JSAutoStopWatch(JSContext *cx MOZ_GUARD_OBJECT_NOTIFIER_PARAM) Nit: this should be explicit to avoid static analysis failures. @@ +422,5 @@ > +struct JSAutoStopWatch MOZ_FINAL > +{ > + inline JSAutoStopWatch(JSContext *cx MOZ_GUARD_OBJECT_NOTIFIER_PARAM) > + : mIsStopWatchOwner(false) > + , mContext(nullptr) Nit: in SM, isStopWatchOwner_/cx_ is more common. Also, you can initialize cx here. @@ +435,5 @@ > + } > + > + if (sIsRunning.get()) { > + // We are already running a stopwatch on this thread. > + // Let's not run two stopwatches at the same time, as Hm, double counting seems nicer to me than ignoring time completely for the current compartment, but I guess we can always change it if it's a problem. @@ +451,5 @@ > + inline ~JSAutoStopWatch() > + { > + if (!mIsStopWatchOwner) { > + return; > + } Nit: no {} for single-line ifs in js/src @@ +480,5 @@ > + uint64_t missedFrames = 16000000; // Duration of one frame, in museconds > + for (int i = 0; i < 8; ++i) { // FIXME: Magic number > + if (duration < missedFrames) { > + break; > + } Nit: no {} @@ +505,5 @@ > + > + MOZ_DECL_USE_GUARD_OBJECT_NOTIFIER > + > +public: > + static ThreadLocal<bool> sIsRunning; I'd just store this as bool in JSRuntime (cx->runtime() gives you the runtime), runtimes are tied to a single thread (workers have their own runtime).

(In reply to Jan de Mooij [:jandem] from comment #27) > Comment on attachment 8546925 [details] [diff] [review] > Per compartment CPU accounting > > Review of attachment 8546925 [details] [diff] [review]: > ----------------------------------------------------------------- > > Sorry for the delay. For some reason I often miss the feedback requests when > I look at the queue. > > Seems reasonable at a quick glance. sfink mentioned nested event loops, do > you want to handle those somewhere? Yes, I suspect that we're going to have very screwed up data if we do not handle those. Sigh. Did I mention that I hate nested event loops? I guess resetting any ongoing stopwatches whenever we enter the event loop would be sufficient. We would lose some data, but normally not too much.

Comment on attachment 8549617 [details] [diff] [review] 1. Per compartment CPU accounting By the way, Aaron, could take a look at the Windows bits?

Comment on attachment 8549617 [details] [diff] [review] 1. Per compartment CPU accounting Review of attachment 8549617 [details] [diff] [review]: ----------------------------------------------------------------- ::: js/src/vm/Interpreter.cpp @@ +428,5 @@ > + const JSCompartment* compartment = cx->compartment(); > + if (compartment->isSystem && !compartment->addonId) { > + // This frame is part of Firefox itself, don't > + // monitor it. > + return; I still think monitoring Firefox's compartments is just as interesting as monitoring addons or content @@ +443,5 @@ > + // time spent in each of these compartments to the time > + // spent in their respective add-on/tab. However, if both > + // A and C are the same add-on, accumulating the time would > + // cause us to actually count the time spent in C twice. > + return; Thinking through this a bit more, we could stop the stopwatch that is currently running and start a new one, remembering the one we stopped such that we can restart it when we stop this new one. Further, (in an A->B->C scenario) we may be able to have our cake and eat it too by reporting to B the total time spent in C when exiting C and thus restarting B's timer. Similarly reporting to A the total of B and C's time when exiting B's compartment. The time spent in calls out of the compartment could be held separately from the time spent in the compartment.

Comment on attachment 8549622 [details] [diff] [review] 2. Dealing with nested event loops (main thread) js::ResetStopWatches is just a function call and then an integer assignment, right? r=me.

(In reply to Boris Zbarsky [:bz] from comment #34) > Comment on attachment 8549622 [details] [diff] [review] > 2. Dealing with nested event loops (main thread) > > js::ResetStopWatches is just a function call and then an integer assignment, > right? Indeed. I exposed it to avoid de-abstracting JSRuntime.

(In reply to Brad Lassey [:blassey] (use needinfo?) from comment #33) > Comment on attachment 8549617 [details] [diff] [review] > 1. Per compartment CPU accounting > > Review of attachment 8549617 [details] [diff] [review]: > ----------------------------------------------------------------- > > ::: js/src/vm/Interpreter.cpp > @@ +428,5 @@ > > + const JSCompartment* compartment = cx->compartment(); > > + if (compartment->isSystem && !compartment->addonId) { > > + // This frame is part of Firefox itself, don't > > + // monitor it. > > + return; > > I still think monitoring Firefox's compartments is just as interesting as > monitoring addons or content Do you want this in v1? If possible, I would prefer doing this as a followup. > @@ +443,5 @@ > > + // time spent in each of these compartments to the time > > + // spent in their respective add-on/tab. However, if both > > + // A and C are the same add-on, accumulating the time would > > + // cause us to actually count the time spent in C twice. > > + return; > > Thinking through this a bit more, we could stop the stopwatch that is > currently running and start a new one, remembering the one we stopped such > that we can restart it when we stop this new one. > > Further, (in an A->B->C scenario) we may be able to have our cake and eat it > too by reporting to B the total time spent in C when exiting C and thus > restarting B's timer. Similarly reporting to A the total of B and C's time > when exiting B's compartment. The time spent in calls out of the compartment > could be held separately from the time spent in the compartment. Own time and total time? This certainly sounds possible. I fear that this is going to complicate the code (and slow it down), though. I'll experiment and see what this gives. However, would you be ok with landing this v1 with just the total time, and doing this in a followup?

Comment on attachment 8549617 [details] [diff] [review] 1. Per compartment CPU accounting Review of attachment 8549617 [details] [diff] [review]: ----------------------------------------------------------------- Looks good, mostly nits below but I'd like to take a quick look at it when those are addressed. SpiderMonkey style is different from Gecko style and we're pretty strict about it :) ::: js/src/jscompartment.h @@ +176,5 @@ > + // missedFrames[i] == number of times > + // execution of this compartment caused us to > + // miss at least 2^i successive frames - we > + // assume that a frame lasts 16ms. > + uint64_t missedFrames[8]; // FIXME: Magic number Fix the FIXME. Also, shouldn't this class have a constructor to initialize its fields to 0? @@ +188,5 @@ > + // Total number of time code was executed in this > + // compartment, in milliseconds, since process launch. > + uint64_t visits; > + }; > + struct Performance performance; Nit: remove the `struct`. ::: js/src/jspubtd.h @@ +493,5 @@ > + * Reset any stopwatch currently measuring. > + * > + * This function is designed to be called when we process a new event. > + */ > +void ResetStopWatches(JSRuntime*); Move this into jsapi.h, inside the JS namespace. I think you also need: extern JS_PUBLIC_API(void) Like the other functions there have. ::: js/src/vm/Interpreter.cpp @@ +419,5 @@ > > +/** > + * Implementation of per-compartment performance measurement. > + */ > +struct JSAutoStopWatch MOZ_FINAL Nit: move it into the js namespace and call it AutoStopwatch (lower-case W everywhere else too). @@ +442,5 @@ > + // different add-ons/tabs, then we should accumulate the > + // time spent in each of these compartments to the time > + // spent in their respective add-on/tab. However, if both > + // A and C are the same add-on, accumulating the time would > + // cause us to actually count the time spent in C twice. Couldn't we avoid this by setting a flag on the compartment whenever we're measuring? @@ +468,5 @@ > + return; > + > +#endif // defined(XP_UNIX) || defined(XP_WIN) > + > + cx->runtime()->stopWatchOwner = reinterpret_cast<uintptr_t>(this); Nit: I'd prefer making stopWatchOwner an AutoStopwatch* instead of uintptr_t, so that you don't need those casts. You can forward declare the class in Runtime.h; we don't need to move the class to that header. @@ +479,5 @@ > + // we never acquired it, or because we have entered a nested > + // event loop. > + // > + // If there is any ongoing measure, discard it. > + // Remove this line. @@ +485,5 @@ > + } > + runtime->stopWatchOwner = 0; > + > + // Durations in museconds > + uint64_t user_time, system_time; Nit: userTime, systemTime @@ +489,5 @@ > + uint64_t user_time, system_time; > + > +#if defined(XP_UNIX) > + > + Nit: remove those empty lines, here and before the #elif. @@ +515,5 @@ > + &creationTime, &exitTime, > + &kernelTime, &userTime); > + MOZ_ASSERT(success); > + if (!success) > + return; I'd remove the assertion since failure is possible and we do check for it. @@ +541,5 @@ > + uint64_t missedFrames = 16 * 1000; // Duration of one frame, i.e. 16ms in museconds > + for (size_t i = 0; i < ArrayLength(compartment->performance.missedFrames); ++i) { > + if (duration < missedFrames) > + break; > + compartment->performance.missedFrames[i]++ ; Nit: remove whitespace before ';' @@ +545,5 @@ > + compartment->performance.missedFrames[i]++ ; > + missedFrames *= 2; > + } > + } > +private: Nit: indent with two spaces. @@ +572,5 @@ > #ifdef NIGHTLY_BUILD > + // > + // Performance measurements. As there is an observable overhead, > + // for the moment, they should be executed only on Nightly builds. > + // Style nit: remove first and last line. Also, what's the overhead when running a typical benchmark like Octane or Sunspider? If it's measurable we probably need some way to disable it on AWFY etc. ::: js/src/vm/Runtime.cpp @@ +866,5 @@ > > #endif // DEBUG > + > +void > +js::ResetStopWatches(JSRuntime* rt) Nit: JSRuntime *rt ::: js/src/vm/Runtime.h @@ +1423,5 @@ > * function to assess the size of malloc'd blocks of memory. > */ > mozilla::MallocSizeOf debuggerMallocSizeOf; > + > +public: Nit: Indent with two spaces. @@ +1433,5 @@ > + // If a StopWatch is currently running, the unique ID of the > + // JSAutoStopWatch (implemented a pointer to the stopwatch). > + uintptr_t stopWatchOwner; > + > + void ResetStopWatches() { Nit: resetStopwatches().

(In reply to David Rajchenbach-Teller [:Yoric] (use "needinfo") from comment #36) > (In reply to Brad Lassey [:blassey] (use needinfo?) from comment #33) > > Comment on attachment 8549617 [details] [diff] [review] > > > > I still think monitoring Firefox's compartments is just as interesting as > > monitoring addons or content > > Do you want this in v1? If possible, I would prefer doing this as a followup. > > Own time and total time? This certainly sounds possible. I fear that this is > going to complicate the code (and slow it down), though. I'll experiment and > see what this gives. However, would you be ok with landing this v1 with just > the total time, and doing this in a followup? yea, no problem landing something and then iterating.

Comment on attachment 8549617 [details] [diff] [review] 1. Per compartment CPU accounting Review of attachment 8549617 [details] [diff] [review]: ----------------------------------------------------------------- ::: js/src/vm/Interpreter.cpp @@ +462,5 @@ > + FILETIME exitTime; // Ignored > + > + BOOL success = GetProcessTime(GetCurrentProcessID(), > + &creationTime, &exitTime, > + &mKernelTimeStamp, &mUserTimeStamp); s/GetProcessTime/GetProcessTimes/ (Notice the 's' on the end) @@ +510,5 @@ > + FILETIME creationTime; > + FILETIME exitTime; > + FILETIME kernelTime; > + FILETIME userTime; > + BOOL success = GetProcessTime(GetCurrentProcessID(), s/GetProcessTime/GetProcessTimes/

Comment on attachment 8549617 [details] [diff] [review] 1. Per compartment CPU accounting Review of attachment 8549617 [details] [diff] [review]: ----------------------------------------------------------------- aklotz, I assume you re-requested feedback unintentionally.

/r/2663 - Bug 674779 - Reset the performance stop watch whenever we process the next event /r/2665 - Bug 674779 - Reset the performance stop watch whenever we process the next event on a worker /r/2667 - Bug 674779 - Per-CPU compartment accounting /r/2669 - Bug 674779 - Per-CPU compartment accounting (own and total time) Pull down these commits: hg pull review -r 4b6af5bc23c5275fb34bc155127c1a24c77f0563

So, here is a v2 that attempts to differentiate own time and total time. Code is not entirely finalized, but it now supports turning on/off measurement from JS.

(In reply to David Rajchenbach-Teller [:Yoric] (away until Febrary - use "needinfo") from comment #41) > Created attachment 8551395 [details] > MozReview Request: bz://674779/Yoric I have no idea what to do with this

(In reply to Brad Lassey [:blassey] (use needinfo?) from comment #44) > (In reply to David Rajchenbach-Teller [:Yoric] (away until Febrary - use > "needinfo") from comment #41) > > Created attachment 8551395 [details] > > MozReview Request: bz://674779/Yoric > > I have no idea what to do with this Just click the attachment and it will redirect you to ReviewBoard, our new external and experimental review system.

https://reviewboard.mozilla.org/r/2669/#review2077 Ship It!

Comment on attachment 8551395 [details] MozReview Request: bz://674779/Yoric /r/2663 - Bug 674779 - Reset the performance stop watch whenever we process the next event /r/2665 - Bug 674779 - Reset the performance stop watch whenever we process the next event on a worker /r/2667 - Bug 674779 - Per-CPU compartment accounting /r/2669 - Bug 674779 - Per-CPU compartment accounting (own and total time) /r/3941 - Bug 674779 - Merging cpow measurements and own/system time measurements Pull down these commits: hg pull review -r 7077823cbada87b6022b45fd720c16620acb0ce9

Comment on attachment 8551395 [details] MozReview Request: bz://674779/Yoric /r/2663 - Bug 674779 - Reset the performance stop watch whenever we process the next event /r/2665 - Bug 674779 - Reset the performance stop watch whenever we process the next event on a worker /r/2667 - Bug 674779 - Per-CPU compartment accounting /r/2669 - Bug 674779 - Per-CPU compartment accounting (own and total time) /r/3941 - Bug 674779 - Merging cpow measurements and own/system time measurements Pull down these commits: hg pull review -r 7077823cbada87b6022b45fd720c16620acb0ce9

https://reviewboard.mozilla.org/r/2669/#review3123 Ship It!

Bug 1071880 makes use of nsICompartment::time and was pushed to central after the try-push here. Will these two interfere?

I intend to switch the code landed in bug 1071880 over to use this new interface.

Comment on attachment 8551395 [details] MozReview Request: bz://674779/Yoric https://reviewboard.mozilla.org/r/2661/#review3151 Looks pretty good but still some style issues. If you can post an updated patch I can review quickly :) ::: js/src/jspubtd.h (Diff revision 2) > + // assume that a frame lasts 16ms. Nit: instead of these short lines, use the full 80 characters per line (for comments, 99 for code). Same for the comments below. ::: js/src/jsutil.h (Diff revision 2) > + Nit: don't add an extra newline here. ::: js/src/vm/Runtime.h (Diff revision 2) > + struct StopWatch { Stopwatch (lowercase 'w') ::: js/src/vm/Runtime.h (Diff revision 2) > + js::AutoStopwatch* owner; '*' goes before the name, in js/src ::: js/src/vm/Runtime.h (Diff revision 2) > + void Reset() { s/Reset/reset/ ::: js/src/vm/Runtime.h (Diff revision 2) > +public: Nit: indent with two spaces ::: js/src/vm/Interpreter.cpp (Diff revision 2) > + * Implementation of per-compartment performance measurement. This class uses both // and /* */ comments. Please use the former everywhere. ::: js/src/vm/Interpreter.cpp (Diff revision 2) > + } No {} ::: js/src/vm/Interpreter.cpp (Diff revision 2) > + JSCompartment* compartment = context_->compartment(); '*' goes before the name. ::: js/src/vm/Interpreter.cpp (Diff revision 2) > + uint64_t descendentsSystemTime; Please use a _ prefix for all members, if you use one for parent_ and context_. ::: js/src/vm/Interpreter.cpp (Diff revision 2) > + js::AutoStopwatch stopWatch(cx); lowercase 'W'

Comment on attachment 8551395 [details] MozReview Request: bz://674779/Yoric /r/2663 - Bug 674779 - Reset the performance stop watch whenever we process the next event /r/2665 - Bug 674779 - Reset the performance stop watch whenever we process the next event on a worker /r/2667 - Bug 674779 - Per-CPU compartment accounting /r/2669 - Bug 674779 - Per-CPU compartment accounting (own and total time) /r/3941 - Bug 674779 - Merging cpow measurements and own/system time measurements /r/4045 - Bug 674779 - Add per-compartment CPU accounting - stylefixes;r=jandem Pull down these commits: hg pull review -r aef01ec09647d1fb319adc64f84d306e4399f0a3

Comment on attachment 8551395 [details] MozReview Request: bz://674779/Yoric https://reviewboard.mozilla.org/r/2661/#review3273 Ship It!

Comment on attachment 8551395 [details] MozReview Request: bz://674779/Yoric https://reviewboard.mozilla.org/r/2661/#review3279 r=me on the js/src changes. Thanks for putting up with me! ::: js/src/jsapi.cpp (Diff revision 3) > +js::GetPerformanceData(JSCompartment *cx) JSCompartment *cx is confusing (cx usually refers to a JSContext*), so rename it to 'comp' or 'c'.

Comment on attachment 8551395 [details] MozReview Request: bz://674779/Yoric /r/2663 - Bug 674779 - Reset the performance stop watch whenever we process the next event /r/2665 - Bug 674779 - Reset the performance stop watch whenever we process the next event on a worker /r/2667 - Bug 674779 - Per-CPU compartment accounting /r/2669 - Bug 674779 - Per-CPU compartment accounting (own and total time) /r/3941 - Bug 674779 - Merging cpow measurements and own/system time measurements /r/4045 - Bug 674779 - Add per-compartment CPU accounting - stylefixes;r=jandem /r/4159 - Bug 674779 - Add per-compartment CPU accounting - stylefixes;r=jandem /r/4161 - Bug 674779 - Per-CPU compartment accounting (test);r=blassey Pull down these commits: hg pull review -r 0eadb6a94d1c65c5f97db4f18c5b04028ccad25e

Taking the opportunity to add a test.

Comment on attachment 8551395 [details] MozReview Request: bz://674779/Yoric https://reviewboard.mozilla.org/r/2661/#review3325 Ship It!

Fixes: https://treeherder.mozilla.org/#/jobs?repo=try&revision=46c04a371b8e

Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=55b345e9493f

Folding the patch with a few typo fixes in the Windows build, a small test fix that makes the test less fragile wrt to JS optimizations, and a little bit of e10s testing.

Kyle, we can land the patch without part 2., but it would still be nice to have a review.

A few trivial changes discussed over IRC with blassey. Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=13dcb22d14dd

Taking the opportunity to add FAIL_ON_WARNINGS = True to moz.build. Above Try had failures on Windows 64, but they appear unrelated to my patch. Here's the Try with Win 32, as it should have been: https://treeherder.mozilla.org/#/jobs?repo=try&revision=e9f9cdc7eb35

Bitrotted, please rebase. Also, does this need a leave-open for part 3?

Unbitrotten. I will move part 3 to another bug.

jmaher, be informed that this patch may cause performance regressions.

thanks for the heads up- we should know tomorrow what type of effect this has.

https://hg.mozilla.org/integration/mozilla-inbound/rev/d7d9bbfa72c5 Note that I had to bump the nsIXPCComponents_Utils UUID before pushing. Please be more conscientious of that in the future when changing interfaces.

I had to back this out in https://hg.mozilla.org/integration/mozilla-inbound/rev/00ccf3b425fd for mochitest-bc orange: https://treeherder.mozilla.org/logviewer.html#?job_id=7048346&repo=mozilla-inbound

I'm on it. At first sight, this looks like a trivial error in the test I have added.

So far, the tests look good.

I think Yoric is going to spin off another bug for what I need to review, or something.

So, I still have two oranges that prevent me from relanding. One is an frequent WinXP orange, by which the time elapsed is often 0µs. I have tried many workarounds, to no avail, and I am starting suspect that this is related to the resolution of the performance clock. Since this is WinXP only and the only fallback of this bug would be not reporting slow add-ons, I believe that this should not be a blocker. The fix would be provided by bug 1134591, which is definitely not trivial for power usage reasons. The other blocker is that the patch makes bug 1094218 perma-orange under Linux. I'm investigating.

See http://blog.kalmbachnet.de/?postid=28 for a possible cause of the Windows XP bug.

here is the performance hit of this: http://alertmanager.allizom.org:8080/alerts.html?rev=b1f4b4120e21&showAll=1 and the corresponding win after backing it out: http://alertmanager.allizom.org:8080/alerts.html?rev=577937f4dce7&showAll=1

That's a pretty steep hit. We need to decide whether we are willing to land this or we wish to switch to bug 1137522 or bug 1134591 instead.

(In reply to Nicholas Nethercote [:njn] from comment #15) >In comparison, > about:memory is extremely useful for investigating individual sessions. I > suspect per-compartment CPU accounting would be similar -- great when a > single user has bad performance, but of little use in aggregate. Plus you > can't report content URLs without violating user privacy... As a user I could do with something like about:compartments with a column for memory usage associated with an addon. About:memory is just a big heap of noise for me for the most part. Hard to derive any useful information.

Comment on attachment 8551395 [details] MozReview Request: bz://674779/Yoric /r/2663 - Bug 674779 - Per-component CPU monitoring, low-level;r=blassey,jandem /r/2665 - Bug 674779 - Per-component CPU monitoring, high-level;r=blassey,froydnj Pull down these commits: hg pull review -r 2d1c8da21bc81b80d60d95edb01031eab8e37b27

Yoric: you don't have to put a link to every try job you push. It's just bugspam.

I can't figure out whether that last push was out of spite or not. Yoric, please clarify. ;-)

Er... I didn't put this link, at least not manually. I'll check if I have some hg hook that does it behind my back.

It's bzpost, described at http://mozilla-version-control-tools.readthedocs.org/en/latest/hgext.html as "The bzpost extension will automatically update Bugzilla with comments containing the URL to pushed changesets after pushing changesets that reference bugs. The implementation is highly tailored towards the Firefox workflow." "mach mercurial-setup" installs it/advises installing it. See https://dxr.mozilla.org/mozilla-central/source/tools/mercurial/hgsetup/wizard.py#129 and related lines.

Ok, that extension would be useful if I could somehow control it. Deactivated.

The new version I have uploaded for review implements the strategy introduced in bug 1137522. Here are the numbers from Talos, which I think are pretty acceptable: https://compare-talos.paas.mozilla.org/?oldBranch=Try&oldRevs=0aca19bcacd3&newBranch=Try&newRev=cfc5136993bc&submit=true

Comment on attachment 8551395 [details] MozReview Request: bz://674779/Yoric https://reviewboard.mozilla.org/r/2661/#review4035 please use hg move to move and/or rename the files. This is currently just deleting the existing files and creating new ones, which looses revision history (or at least that's how it looks in review board).

That's what I've done, so I blame review board.

Posting on splinter as per blassey's request.

Comment on attachment 8551395 [details] MozReview Request: bz://674779/Yoric /r/2663 - Bug 674779 - Per-component CPU monitoring, low-level;r=blassey,jandem /r/2665 - Bug 674779 - Per-component CPU monitoring, high-level;r=blassey,froydnj Pull down these commits: hg pull review -r 82e7dcf782c0fc5f9b9f13a5b8e4c4c463268737

Comment on attachment 8574706 [details] [diff] [review] 2. High-level changes Review of attachment 8574706 [details] [diff] [review]: ----------------------------------------------------------------- ::: toolkit/modules/AddonWatcher.jsm @@ +129,5 @@ > + missedFrames: item.getMissedFrames(), > + totalCPOWTime: item.totalCPOWTime, > + }; > + let previous = this._previousPerformanceIndicators[addonId]; > + update[addonId] = current; I see you setting update[addonId] and getting from this._previousPerformanceIndicators[addonId], but not using the former or setting the latter.

I found other errors in my patch to AddonWatcher.jsm. I'll try and add some basic unit tests.

Ok, I decided that we couldn't let AddonWatcher.jsm continue without unit tests. I broke it too easily. 1. Fixes to AddonWatcher.jsm; 2. Unit tests for AddonWatcher.jsm; 3. I took the opportunity to add Telemetry reporting of misbehaving addons.

Comment on attachment 8576080 [details] [diff] [review] 2.a High-level changes (cumulative patch) Review of attachment 8576080 [details] [diff] [review]: ----------------------------------------------------------------- Looks good to me, will need review from a toolkit peer though, so requesting review from mossop

Yoric, can you post an interdiff of your changes? Reviewing large patches takes time and I'm only interested in the changes since the last review.

Actually, given that I change just about everything, the interdiff is almost twice as large as the entire patch, so I figured the full patch would be much simpler to review.

Comment on attachment 8574705 [details] [diff] [review] 1. Low-level changes Review of attachment 8574705 [details] [diff] [review]: ----------------------------------------------------------------- Sorry for the delay. Mostly style nits below. ::: js/src/jsapi.cpp @@ +178,5 @@ > + js::SystemAllocPolicy> Set; > + Set set; > + if (!set.init(100)) { > + return false; > + } No {} ::: js/src/jspubtd.h @@ +480,5 @@ > }; > > +// Container for performance data > +// All values are monotonic. > +struct PerformanceData { Can we add these structs to jsapi.h instead of jspubtd.h? @@ +501,5 @@ > + uint64_t ticks; > + > + PerformanceData() > + : totalUserTime(0) > + , totalSystemTime(0) Indent with two spaces less. @@ +508,5 @@ > + { > + memset(missedFrames, 0, sizeof(missedFrames)); > + } > + PerformanceData(const PerformanceData& from) > + : totalUserTime(from.totalUserTime) And here. @@ +545,5 @@ > + // `true` if an instance of `AutoStopwatch` is already monitoring > + // the performance of this performance group for this iteration > + // of the event loop, `false` otherwise. > + bool HasStopwatch(uint64_t iteration) { > + return stopwatch_ != nullptr && iteration_ == iteration; hasStopwatch. Also can make this method 'const' while you're here. @@ +550,5 @@ > + } > + > + // Mark that an instance of `AutoStopwatch` is monitoring > + // the performance of this group for a given iteration. > + void AcquireStopwatch(uint64_t iteration, struct AutoStopwatch* stopwatch) { acquiteStopwatch, remove the "struct" and AutoStopWatch *stopwatch. Also below. @@ +559,5 @@ > + // performance of this group for the iteration. > + void ReleaseStopwatch(uint64_t iteration, struct AutoStopwatch* stopwatch) { > + if (iteration_ != iteration) { > + return; > + } No {} @@ +565,5 @@ > + stopwatch_ = nullptr; > + } > + PerformanceGroup() > + : stopwatch_(nullptr) > + , iteration_(0) Indent with 2 spaces less. @@ +572,5 @@ > + ~PerformanceGroup() > + { > + MOZ_ASSERT(refCount_ == 0); > + } > +private: Indent with two spaces. @@ +575,5 @@ > + } > +private: > + // The stopwatch currently monitoring the group, > + // or `nullptr` if none. Used ony for comparison. > + struct AutoStopwatch* stopwatch_; AutoStopwatch *stopwatch_. Also can we remove the "struct" here? Do you need to forward declare it then? That's what we do elsewhere. @@ +592,5 @@ > +struct PerformanceGroupHolder { > + // Get the group. > + // On first call, this causes a single Hashtable lookup. > + // Successive calls do not require further lookups. > + js::PerformanceGroup* GetGroup(); js::PerformanceGroup *getGroup(); @@ +599,5 @@ > + , compartment_(compartment) > + , group_(nullptr) > + { } > + ~PerformanceGroupHolder(); > +private: Indent with two spaces. ::: js/src/vm/Interpreter.cpp @@ +433,5 @@ > + // stopwatch. > + // > + // Previous owner is restored upon destruction. > + explicit inline AutoStopwatch(JSContext *cx MOZ_GUARD_OBJECT_NOTIFIER_PARAM) > + : cx_(cx) Nit: indent these lines with 2 spaces less. @@ +500,5 @@ > + group_->ReleaseStopwatch(iteration_, this); > + uint64_t userTimeEnd, systemTimeEnd; > + if (!this->GetTimes(&userTimeEnd, &systemTimeEnd)) { > + return; > + } No {} @@ +522,5 @@ > + runtime->stopwatch.isEmpty = true; > + } > + } > + > + private: Indent with 2 spaces instead of 1. @@ +528,5 @@ > + // Update an array containing the number of times we have missed > + // at least 2^0 successive frames, 2^1 successive frames, ... > + // 2^i successive frames. > + template<typename T, int N> > + void UpdateMissedFrames(uint64_t totalTimeDelta, T (&array)[N]) { updateMissedFrames. @@ +540,5 @@ > + } > + > + // Get the OS-reported time spent in userland/systemland, > + // in microseconds. > + bool GetTimes(uint64_t *userTime, uint64_t *systemTime) { getTimes @@ +558,5 @@ > +#endif // defined(RUSAGE_THREAD) > + MOZ_ASSERT(!err); > + if (err) { > + return false; > + } No {}. Also I'd remove the MOZ_ASSERT: either we think it can fail and we should handle it, or we know it can't fail and we assert/MOZ_CRASH. @@ +577,5 @@ > + BOOL success = GetThreadTimes(GetCurrentThread(), > + &creationFileTime, &exitFileTime, > + &kernelFileTime, &userFileTime); > + MOZ_ASSERT(success); > + if (!success) And here. ::: js/src/vm/Runtime.cpp @@ +873,5 @@ > + if (!group_) { > + // The group has never been instantiated. > + return; > + } > + if (--(group_->refCount_) > 0) { We should assert against underflow here. Maybe add a decRefCount method? @@ +877,5 @@ > + if (--(group_->refCount_) > 0) { > + // The group has at least another owner. > + return; > + } > + delete group_; js_delete(group_); @@ +881,5 @@ > + delete group_; > +} > + > +PerformanceGroup * > +js::PerformanceGroupHolder::GetGroup() { '{' on next line @@ +897,5 @@ > + PerformanceGroup* group; > + if (compartment->isSystem) { > + // Addon or built-in > + GroupsByAddons::AddPtr ptr = > + groupsByAddon.lookupForAdd(compartment->addonId); Nit: should fit on one line (99 chars for code). @@ +904,5 @@ > + group = runtime->new_<js::PerformanceGroup>(); > + groupsByAddon.add(ptr, compartment->addonId, group); > + } else { > + // Web page > + JSPrincipals* principals = JS_GetCompartmentPrincipals(compartment); JSPrincipals *principals @@ +906,5 @@ > + } else { > + // Web page > + JSPrincipals* principals = JS_GetCompartmentPrincipals(compartment); > + GroupsByPrincipals::AddPtr ptr = > + groupsByPrincipals.lookupForAdd(principals); Nit: one line. Also I'm not familiar with the way principals are (re)used across compartments. We could also use the Zone in this case maybe. Can you discuss this with bholley or bz? ::: js/src/vm/Runtime.h @@ +1449,5 @@ > + * `true` if stopwatch monitoring is active, `false` otherwise. > + */ > + bool isActive; > + > + js::PerformanceData performance; Newline after this line, and add a comment here too. @@ +1453,5 @@ > + js::PerformanceData performance; > + Stopwatch() > + : iteration(0) > + , isEmpty(true) > + , isActive(false) Indent with two spaces less. @@ +1465,5 @@ > + > + /** > + * Reset the stopwatch. > + * > + * This method is meant to be called whewnever we start processing "whenever" @@ +1474,5 @@ > + ++iteration; > + isEmpty = true; > + } > + > + js::PerformanceGroup *GetGroup(JSCompartment *compartment); getGroup

(In reply to Jan de Mooij [:jandem] from comment #116) > @@ +558,5 @@ > > +#endif // defined(RUSAGE_THREAD) > > + MOZ_ASSERT(!err); > > + if (err) { > > + return false; > > + } > > No {}. > > Also I'd remove the MOZ_ASSERT: either we think it can fail and we should > handle it, or we know it can't fail and we assert/MOZ_CRASH. Well, I don't *think* we can fail, but for all I know, there are exotic sandboxes that can cause calls to `getrusage` to fail. If we fail in a debug build, I'd be interested in crashing/knowing, but in release, it's not that important, so I'm willing to let it slip. In other words, I would tend to keep MOZ_ASSERT, if that's ok with you. > @@ +906,5 @@ > > + } else { > > + // Web page > > + JSPrincipals* principals = JS_GetCompartmentPrincipals(compartment); > > + GroupsByPrincipals::AddPtr ptr = > > + groupsByPrincipals.lookupForAdd(principals); > > Nit: one line. > > Also I'm not familiar with the way principals are (re)used across > compartments. We could also use the Zone in this case maybe. Can you discuss > this with bholley or bz? Are you talking about non-sandboxed iframes and Harmony modules?

Comment on attachment 8551395 [details] MozReview Request: bz://674779/Yoric /r/2663 - Bug 674779 - Per-component CPU monitoring, low-level;r=blassey,jandem /r/2665 - Bug 674779 - Per-component CPU monitoring, high-level;r=blassey,froydnj /r/5107 - Bug 674779 - Fixes to AddonWatcher.jsm;r=blassey /r/5249 - Bug 674779 - Per-component CPU monitoring, low-level (fixups);r=jandem Pull down these commits: hg pull review -r b29787658d4c8c16f650b95933c90bfd0fd28a67

Applied feedback. I have also realized that we never removed stuff from out PerformanceGroup hashtables, so I have added cleanup.

https://reviewboard.mozilla.org/r/2665/#review4257 ::: toolkit/components/aboutperformance/moz.build (Diff revision 4) > +BROWSER_CHROME_MANIFESTS += ['tests/mochi/browser.ini'] Can you put these in tests/browser ::: toolkit/components/aboutperformance/nsIPerformanceStats.idl (Diff revision 4) > + readonly attribute AString name; I'm not sure what this is saying perhaps some examples would help. Does it mean if the component is a webpage this returns just "webpage" or the page title. Or is it the URL, which I wouldn't consider human readable. In the case of a webpage is there any way to get the DOM window for the page or something so we can track this back to tabs? ::: toolkit/components/aboutperformance/nsIPerformanceStats.idl (Diff revision 4) > +interface nsIPerformanceStats: nsISupports { The docs throughout refer to this as a component, would it make sense to name this nsIComponentStats? ::: toolkit/components/aboutperformance/nsIPerformanceStats.idl (Diff revision 4) > + readonly attribute bool isSystem; Does this imply than an add-on can have multiple components? ::: toolkit/components/aboutperformance/nsIPerformanceStats.idl (Diff revision 4) > + * `nsIPerformanceStatsService.isStopwatchActive` is `true`. This should mention that this is a snapshot of performance rather than something whose properties would be expected to change over time. ::: toolkit/components/aboutperformance/content/aboutPerformance.js (Diff revision 4) > + for (let i = 0; i < performanceData.MISSED_FRAME_RANGE; ++i) { I don't see MISSED_FRAME_RANGE defined anywhere ::: toolkit/components/aboutperformance/content/aboutPerformance.js (Diff revision 4) > + result.missedFrames[i] = performanceData.getMissedFrames[i]; getMissedFrames is a function ::: toolkit/components/aboutperformance/content/aboutPerformance.js (Diff revision 4) > +function exportStatistics(performanceData) { Any particular reason for not just putting all of this in the PerformancePrincipal function? ::: toolkit/components/aboutperformance/nsIPerformanceStats.idl (Diff revision 4) > +interface nsIPerformanceSnapshot: nsISupports { Is it possible to add an attribute indicating how much realtime has been monitored to generate these figures? It would be useful to display on the stats page to give the numbers more meaning. ::: toolkit/components/aboutperformance/tests/mochi/browser_compartments.js (Diff revision 4) > +function* promiseTabLoadEvent(tab, url) BrowserTestUtils.browserLoaded ::: toolkit/components/aboutperformance/tests/mochi/browser_compartments.js (Diff revision 4) > + mm.loadFrameScript(script, true); Just add the frame script to the test tab you create ::: toolkit/components/aboutperformance/tests/mochi/browser_compartments.js (Diff revision 4) > + info(JSON.stringify(stats, null, "\t")); Is this just accidentally left in? I don't think we need it. ::: toolkit/components/aboutperformance/tests/mochi/browser_compartments.js (Diff revision 4) > + }); Might be worth some other checks here, like does totalUserTime only ever increase. ::: toolkit/components/aboutperformance/tests/mochi/content.js (Diff revision 4) > +"use strict"; You might find ContentTask easier than maintaining a separate file. ::: toolkit/components/aboutperformance/tests/xpcshell/test_compartments.js (Diff revision 4) > +/* Why is this block commented out? ::: toolkit/components/aboutperformance/tests/xpcshell/test_compartments.js (Diff revision 4) > + let stats3 = yield promiseStatistics("Third burn, without stopwatch"); This result is never used ::: browser/base/content/test/social/browser_addons.js (Diff revision 4) > + registerCleanupFunction(() => {AddonWatcher = isWatcherPaused;}); Maybe you mean "AddonWatcher.isPaused" here. I'm not sure why this is necesssary though, you don't seem to actually pause it at all. ::: toolkit/modules/AddonWatcher.jsm (Diff revision 4) > + continue; You never add to _previousPerformanceIndicators so you probably never see a slow add-on ::: toolkit/modules/AddonWatcher.jsm (Diff revision 4) > + gravity = current.totalCPOWTime - previous.totalCPOWTime; I don't think we want to warn on any cpow time at all, that is going to flag a lot of add-ons. We should start with the worst offenders and then tighten this over time. What's the story with isStopwatchActive? Does it cost performance to have it just enabled all the time? As it is it will be enabled all the time anyway because of AddonWatcher so I don't know what being able to disable it gives us. There is also a problem with a simple boolean, about:performance disables it when unloaded right now, which will stop AddonWatcher working. You can't just remember the previous setting either unless you assume those are the only two consumers ever.

Comment on attachment 8551395 [details] MozReview Request: bz://674779/Yoric https://reviewboard.mozilla.org/r/2661/#review4301 Ship It!

Comment on attachment 8551395 [details] MozReview Request: bz://674779/Yoric Didn't look at the C++ parts but enough comment here to need another look after they've been addressed. It's a little frustrating that stuff that is broken in one change is fixed in the next as it made me spend time finding errors you already knew about.

Comment on attachment 8574706 [details] [diff] [review] 2. High-level changes Review of attachment 8574706 [details] [diff] [review]: ----------------------------------------------------------------- Assuming this is the same as the changes in mozreview

Comment on attachment 8576080 [details] [diff] [review] 2.a High-level changes (cumulative patch) Assuming this is the same as the changes in mozreview

https://reviewboard.mozilla.org/r/2665/#review4303 ::: browser/base/content/test/social/browser_addons.js (Diff revision 4) > + registerCleanupFunction(() => {AddonWatcher = isWatcherPaused;}); Good point. It looks like I somehow fixed the issue without pausing the AddonWatcher or ever finding out what caused it.

Comment on attachment 8551395 [details] MozReview Request: bz://674779/Yoric /r/2663 - Bug 674779 - Per-component CPU monitoring, low-level;r=blassey,jandem /r/2665 - Bug 674779 - Per-component CPU monitoring, high-level;r=blassey,froydnj /r/5107 - Bug 674779 - High-level fixes;r=blassey Pull down these commits: hg pull review -r 7f5064bee40d4965cd2659415530c4b805794994

https://reviewboard.mozilla.org/r/5107/#review4405 ::: toolkit/components/aboutperformance/content/aboutPerformance.js (Diff revision 2) > - for (let {key} of MEASURES) { > + for (let {key} of [...MEASURES, "missedFrames"] ) { missedFrames is not an attribute of nsIPerformanceStats ::: toolkit/modules/AddonWatcher.jsm (Diff revision 2) > + // By default, warn if we have skipped at least once 4 consecurive frames Nit: consecutive ::: toolkit/modules/AddonWatcher.jsm (Diff revision 2) > + totalCPOWTime: Preferences.get("browser.addon-watch.limits.totalCPOWTime", 1000) * 1000, Interval can change so we should scale this accordingly Seem to be some questions I asked last time around not answered, I'd like to see those answered before r+ here. I'm not entirely sure the gravity value from AddonWatcher is useful right now, I'd like to see what we're planning on using it for.

Quick update: I had to spend a few days hunting down an elusive segfault. I believe that I have solved it, so I will upload updated patches soon.

Comment on attachment 8551395 [details] MozReview Request: bz://674779/Yoric /r/2663 - Bug 674779 - Per-component CPU monitoring, low-level;r=blassey,jandem /r/2665 - Bug 674779 - Per-component CPU monitoring, high-level;r=blassey,froydnj /r/5107 - Bug 674779 - High-level fixes;r=blassey /r/5937 - Bug 674779 - High-level fixes;r=mossop /r/5939 - Bug 674779 - Low-level fixes;r=jandem Pull down these commits: hg pull review -r c559a784c96ba133e142e6ec8871cc60c9c82be8

Also available on MozReview: https://reviewboard.mozilla.org/r/5939/ Summary of changes: - applied feedback; - PerformanceGroup instances are now properly removed from the hashmap once their refcount is 0; - merged the two instances of HashMap in Runtime::Stopwatch into a single; - simplified the code that dealt with this map; - as this caused crashes, any change to isSystem or principals of a JSCompartment will now unlink the PerformanceGroupHolder from its PerformanceGroup – also, to avoid regressions, hidden both fields behind methods and made addonId a *const; - an AutoStopwatch now doesn't capture its PerformanceGroup or its JSContext.

Also available on MozReview: https://reviewboard.mozilla.org/r/5937/ Summary of changes: - applied feedback; - more sanity-check tests; - added PerformanceStats.jsm, which provides a nicer JS API on top of nsIPerformanceStatsService (and which proved quite useful for tracking bugs); - updated about:performance to display the jank and to show time values as a percentage of wallclock time, which makes it actually somewhat useful; - updated code to take advantage of PerformanceStats.jsm; - update nsPerformanceStats.cpp to fix several bugs; - code doesn't attempt to set PerformanceStats.isStopwatchActive to false anymore.

Comment on attachment 8582453 [details] [diff] [review] 4. High-level changes, part 3 Review of attachment 8582453 [details] [diff] [review]: ----------------------------------------------------------------- A couple of questions, some from my earlier reviews that I never saw answered: Can add-ons appear as multiple components given that they can create sandboxes with differing principals? Is it possible to add an attribute to nsIPerformanceSnapshot indicating how much realtime has been monitored to generate these figures? It would be useful to display on the stats page to give the numbers more meaning. I'm not entirely sure the gravity value from AddonWatcher is useful right now, I'd like to see what we're planning on using it for. Given that this will be turned on all the time in Firefox do we actually need isStopwatchActive? ::: toolkit/components/aboutperformance/nsIPerformanceStats.idl @@ +83,3 @@ > > /** > * Information on the process itself. It's not terribly clear to me what this actually means, is it just the sum of all components? ::: toolkit/modules/AddonWatcher.jsm @@ +16,5 @@ > "resource://gre/modules/Preferences.jsm"); > XPCOMUtils.defineLazyModuleGetter(this, "console", > "resource://gre/modules/devtools/Console.jsm"); > +XPCOMUtils.defineLazyModuleGetter(this, "PerformanceStats", > + "resource://gre/modules/PerformanceStats.jsm"); You already imported it above, no need for both ::: toolkit/modules/PerformanceStats.jsm @@ +65,5 @@ > + for (let k of PROPERTIES_FLAT) { > + this[k] = xpcom[k]; > + } > + this.missedFrames = xpcom.getMissedFrames(); > + Object.freeze(this); Any particular reason we need to freeze this? @@ +98,5 @@ > + * `PerformanceData` in which all numeric values are 0. > + * > + * @return {PerformanceDiff} > + */ > + delta: function(to = null) { compareTo is a better name @@ +117,5 @@ > + } > + > + if (old) { > + for (let i = 0; i < current.missedFrames.length; ++i) { > + this.missedFrames[i] = current.missedFrames[i] - old.missedFrames[i]; Are the two arrays guaranteed to be the same length? @@ +125,5 @@ > + } > + } else { > + for (let i = 0; i < current.missedFrames.length; ++i) { > + this.missedFrames[i] = current.missedFrames[i]; > + } this.missedFrames = current.missedFrames.slice(0); @@ +131,5 @@ > + this[k] = current[k]; > + } > + } > + > + this.jankLevel = 0; Let's be more descriptive of what this actually is. mostMissedFrames maybe? @@ +137,5 @@ > + if (this.missedFrames[i] > 0) { > + this.jankLevel = i + 1; > + break; > + } > + } You can avoid this loop in the case where we have old. @@ +161,5 @@ > + * Get a snapshot of the performance usage of the current process. > + * > + * @type {Snapshot} > + */ > + get snapshot() { Missed this last time round but this, and nsIPerformanceStatsService.snapshot, should instead be a function, getSnapshot(). The reason being that this is a property that changes with each call, PerformanceStats.snapshot !== PerformanceStats.snapshot and even the properties of the object returned will differ. It makes it clear to callers that they should retain the result of getSnapshot rather than assuming PerformanceStats.snapshot always refers to the same stats.

(In reply to Dave Townsend [:mossop] from comment #133) > Comment on attachment 8582453 [details] [diff] [review] > 4. High-level changes, part 3 > > Review of attachment 8582453 [details] [diff] [review]: > ----------------------------------------------------------------- > > A couple of questions, some from my earlier reviews that I never saw > answered: > Can add-ons appear as multiple components given that they can create > sandboxes with differing principals? An add-on is a single component – at VM level, an add-on is known by its add-on ID, not by its principals. It might theoretically be possible for an add-on to dynamically create another add-on, but I doubt we care about that scenario. > Is it possible to add an attribute to nsIPerformanceSnapshot indicating how > much realtime has been monitored to generate these figures? It would be > useful to display on the stats page to give the numbers more meaning. Yes, but I'm not entirely sure how we should define this. Do you mind waiting for a followup bug to add this data? > I'm not entirely sure the gravity value from AddonWatcher is useful right > now, I'd like to see what we're planning on using it for. For the moment, I do not have clear scenario, so I suppose I could get rid of it. > Given that this will be turned on all the time in Firefox do we actually > need isStopwatchActive? Firefox may not need it, but after discussing with the JS team, SpiderMonkey itself needs to the feature to be off by default. That's the best way I found to make this happen. Also, we don't really care about the stopwatch during startup or shutdown, so we may wish to deactivate it during both. > ::: toolkit/components/aboutperformance/nsIPerformanceStats.idl > @@ +83,3 @@ > > > > /** > > * Information on the process itself. > > It's not terribly clear to me what this actually means, is it just the sum > of all components? It's basically all the time spent executing JS code (and native code called from JS code) in the current process + thread. > ::: toolkit/modules/PerformanceStats.jsm > @@ +65,5 @@ > > + for (let k of PROPERTIES_FLAT) { > > + this[k] = xpcom[k]; > > + } > > + this.missedFrames = xpcom.getMissedFrames(); > > + Object.freeze(this); > > Any particular reason we need to freeze this? Not really. It seemed healthy. > > @@ +98,5 @@ > > + * `PerformanceData` in which all numeric values are 0. > > + * > > + * @return {PerformanceDiff} > > + */ > > + delta: function(to = null) { > > compareTo is a better name I agree that `delta` is not a very nice name, but I don't like `compareTo` either, as it really sounds like `equals`. Perhaps `substract`? > @@ +117,5 @@ > > + } > > + > > + if (old) { > > + for (let i = 0; i < current.missedFrames.length; ++i) { > > + this.missedFrames[i] = current.missedFrames[i] - old.missedFrames[i]; > > Are the two arrays guaranteed to be the same length? The arrays all have length 8. > Let's be more descriptive of what this actually is. mostMissedFrames maybe? I had something like that and I changed it to `jankLevel` for some reason I can't remember. Ah, well, let's go for it.

(In reply to David Rajchenbach-Teller [:Yoric] (use "needinfo") from comment #134) > (In reply to Dave Townsend [:mossop] from comment #133) > > Is it possible to add an attribute to nsIPerformanceSnapshot indicating how > > much realtime has been monitored to generate these figures? It would be > > useful to display on the stats page to give the numbers more meaning. > > Yes, but I'm not entirely sure how we should define this. Do you mind > waiting for a followup bug to add this data? Sure, please file it. > > I'm not entirely sure the gravity value from AddonWatcher is useful right > > now, I'd like to see what we're planning on using it for. > > For the moment, I do not have clear scenario, so I suppose I could get rid > of it. I think if we don't know what we're using it for we should drop it. > > Given that this will be turned on all the time in Firefox do we actually > > need isStopwatchActive? > > Firefox may not need it, but after discussing with the JS team, SpiderMonkey > itself needs to the feature to be off by default. That's the best way I > found to make this happen. Also, we don't really care about the stopwatch > during startup or shutdown, so we may wish to deactivate it during both. Ok, maybe make the jsm just turn it on as soon as it is imported and not bother exposing that in the JS API? I just want to avoid the footgun of code turning this off and it breaking features that depend on it. > > @@ +98,5 @@ > > > + * `PerformanceData` in which all numeric values are 0. > > > + * > > > + * @return {PerformanceDiff} > > > + */ > > > + delta: function(to = null) { > > > > compareTo is a better name > > I agree that `delta` is not a very nice name, but I don't like `compareTo` > either, as it really sounds like `equals`. Perhaps `substract`? I can't think of anything better than subtract so let's go with that.

https://reviewboard.mozilla.org/r/6017/#review5003 Applied feedback.

https://reviewboard.mozilla.org/r/6019/#review5005 Fixed a small error in initialization code.

Spotted a small error in initialization path.

Comment on attachment 8551395 [details] MozReview Request: bz://674779/Yoric /r/2663 - Bug 674779 - Per-component CPU monitoring, low-level;r=blassey,jandem /r/2665 - Bug 674779 - Per-component CPU monitoring, high-level;r=blassey,froydnj /r/5107 - Bug 674779 - High-level fixes;r=blassey /r/5937 - Bug 674779 - High-level fixes;r=mossop /r/5939 - Bug 674779 - Low-level fixes;r=jandem /r/6017 - Bug 674779 - High-level fixes;r=mossop /r/6019 - Bug 674779 - Low-level fix;r=jandem /r/6021 - Bug 674779 - More tests;r=mossop Pull down these commits: hg pull review -r 4d96be371b45966e68ae8dcb74d8ee37e34d7fb5

https://reviewboard.mozilla.org/r/6021/#review5009 I took the opportunity to add a few tests and fix stylesheet issues in about:performance.

As https://reviewboard.mozilla.org/r/6019/ – more tests and stylefixes for about:performance.

Dave, the output of reviewboard + bugzilla is somewhat unreadable. Is this a global r+?

(In reply to David Rajchenbach-Teller [:Yoric] (use "needinfo") from comment #144) > Dave, the output of reviewboard + bugzilla is somewhat unreadable. Is this a > global r+? Yes I'm happy with the changes now

Gavin are you ok with adding an about:performance?

Can you summarize what it does and who its intended users are?

It's a top-like tool that displays for each webpage and add-on the amount of CPU, system time, CPOW time, jank during the latest n milliseconds. For the moment, that's only for JS code (including native code called by JS). In future versions, I hope to add memory use and plug-in use. This feature is Nightly-only for the time being, with no definite plans to let it ride the trains. For the moment, the intended users are 1/ us; 2/ add-on developers. I hope to eventually make this useful for power users, but this will require UX and l10n work.

Comment on attachment 8582449 [details] [diff] [review] 3. Low-level changes, part 2 Review of attachment 8582449 [details] [diff] [review]: ----------------------------------------------------------------- Thanks for splitting it up, r=me with nits below addressed. ::: js/src/jsapi.cpp @@ +315,1 @@ > stat->addonId = compartment->addonId; Nit: no {} ::: js/src/jsapi.h @@ +5349,5 @@ > + ~PerformanceGroup() > + { > + MOZ_ASSERT(refCount_ == 0); > + } > +private: Nit: two space indent, and below. @@ +5449,5 @@ > + * compartment). > + */ > +struct PerformanceStats { > + /** > + * If the component is an add-on, the ID of the addon, Here and below you use "component" but elsewhere it's "group" or "performance group". Can we choose one and use it everywhere? I like "performance group" because it's clear it's performance related, and you already have a PerformanceGroup class. @@ +5492,5 @@ > + * all components, and `global` holds a `PerformanceStats` > + * representing the entire process. > + */ > +extern JS_PUBLIC_API(bool) > +JS_GetPerformanceStats(JSRuntime *rt, js::PerformanceStatsVector &stats, js::PerformanceStats &global); Please move this inside the namespace as well and remove the JS_* prefix. ::: js/src/jscompartment.h @@ +145,5 @@ > > public: > + /* > + * The principals associated to this compartment. Note that the > + * same principals may be associated to several compartments and Nit: associated with (twice) @@ +149,5 @@ > + * same principals may be associated to several compartments and > + * that a compartment may change principals during its lifetime > + * (e.g. in case of lazy parsing). > + */ > + inline JSPrincipals *principals() { Please remove the extra whitespace here and below; it's unusual for methods. @@ +159,5 @@ > + > + // If we change principals, we need to unlink immediately this > + // compartment from its PerformanceGroup. For one thing, the > + // performance data we collect should not be improperly associated > + // to a group to which we do not belong anymore. For another thing, Nit: associated with ::: js/src/vm/Interpreter.cpp @@ +610,5 @@ > > private: > // The context with which this object was initialized. > // Non-null. > + JSCompartment *compartment_; Nit: The compartment ::: js/src/vm/Runtime.cpp @@ +907,5 @@ > + (void*)JS_GetCompartmentPrincipals(compartment_); > + // This key may be `nullptr` if we have `isSystem() == true` > + // and `compartment_->addonId`. This is absolutely correct, > + // and this represents the `PerformanceGroup` used to track > + // the performance of the the platform compartments. These 7 lines also appear below. It'd be nice to factor it out, something like this: static void * CompartmentPerformanceGroupKey(JSCompartment *comp) { if (comp->isSystem()) return ...; return ...; } @@ +910,5 @@ > + // and this represents the `PerformanceGroup` used to track > + // the performance of the the platform compartments. > + > + JSRuntime::Stopwatch::Groups::Ptr ptr = > + runtime_->stopwatch.groups_.lookup(key); Nit: fits on one line. @@ +931,5 @@ > + // and this represents the `PerformanceGroup` used to track > + // the performance of the the platform compartments. > + > + JSRuntime::Stopwatch::Groups::AddPtr ptr = > + runtime_->stopwatch.groups_.lookupForAdd(key); And here.

Comment on attachment 8583044 [details] [diff] [review] 5. Low-level changes, part 4 Review of attachment 8583044 [details] [diff] [review]: ----------------------------------------------------------------- ::: js/src/vm/Runtime.h @@ +1500,5 @@ > reset(); > > if (value && !groups_.initialized()) > + if (!groups_.init(128)) > + return false; Nit: add {} to the outer if.

Jandem, Mossop, would you mind if I made a trivial change without review? Avih suggested that "frames" is actually a very ambiguous unit, and we should rather use something clearer, e.g. milliseconds. My patch would involve: - renaming `missedFrames` into `durations` everywhere in the code; - changing the constants so that `durations[0]` == 1ms, ... `durations[7]` == 128ms+; - updating the doc.

(In reply to David Rajchenbach-Teller [:Yoric] (use "needinfo") from comment #152) > Jandem, Mossop, would you mind if I made a trivial change without review? Seems reasonable and indeed clearer than "frames". All this code is still Nightly-only for now, right?

Indeed, that's Nightly-only for now, but since this is going to have an influence on Telemetry, I'd rather fix this before landing.

https://reviewboard.mozilla.org/r/5107/#review5285 Ship It!

Applied feedback, folded the patch, renamed `missedFrames` to `durations` as discussed above.

Folded the patch, renamed `missedFrames` to `duration`.

Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=3b5eec105a42

Mmmh... there's something wrong with this try run.

Oh great, it looks like switching to 1ms of precision highlights the fact that the underlying clocks are not accurate/monotonic enough. Filed bug 1149897. For the moment, I'll try and land the patch without the monotonicity checks, and investigate the issue in bug 1149897. Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=8383446d90cf

Deactivating the test, as this property is not required for the moment. I'm working on an actual fix as part of bug 1149897.

https://hg.mozilla.org/integration/mozilla-inbound/rev/ba375ae024b3 https://hg.mozilla.org/integration/mozilla-inbound/rev/dab734322226 https://hg.mozilla.org/integration/mozilla-inbound/rev/b4efb3f1976f

Self-reviewing trivial patch on a test.

https://hg.mozilla.org/mozilla-central/rev/ba375ae024b3 https://hg.mozilla.org/mozilla-central/rev/dab734322226 https://hg.mozilla.org/mozilla-central/rev/b4efb3f1976f https://hg.mozilla.org/mozilla-central/rev/ab01fd91bc02

Is this normal? Menu Wizard is sitting atop with jank level 10. Which I wouldn't expect because it's only active if I bring up a menu. Also the levels are progressively redder, but level 10 is just plain black like level 0. This seems counterintuitive to me. What's the reason for some addons constantly appearing and disappearing? It seems to me their activation counters are reset for some reason. It's hard to tell anything with addons appeare/disappearing constanlty, but I spotted flashgot appearing with activation numbers between 1-60, and then disappearing. It's activation number doesn't increment when it appears, it seems to be random. Wouldn't all addons normally appear and stay on the list? With numbers either increasing or staying the same?

I'm also seeing negative numbers, e.g. > 0 -8 0 0 8 Flashblock

(In reply to avada from comment #167) > Created attachment 8587411 [details] > about:performance screencast > > Is this normal? > Menu Wizard is sitting atop with jank level 10. Which I wouldn't expect > because it's only active if I bring up a menu. Surprising, but possible. I'd have to look at it. Can you file a bug regarding this behavior wrt Menu Wizard and also a bug regarding this behavior wrt Bugzilla Tweaks? Please file them in "Toolkit:Performance Monitoring", Cc me and make sure that the platform information is correct. > Also the levels are progressively redder, but level 10 is just plain black > like level 0. This seems counterintuitive to me. Filed as bug 1150514. > What's the reason for some addons constantly appearing and disappearing? Addons appear only if they have had some activity during the past ~2 seconds. Note that this is a very early design for about:performance, we haven't even shown it to any ux person yet. If you have suggestions on how to improve the design of about:performance, can you file them as new bugs in component "Toolkit:Performance Monitoring"? > It seems to me their activation counters are reset for some reason. Yes, that's the number of activations in the past ~2 seconds.

(In reply to Avi Halachmi (:avih) from comment #168) > I'm also seeing negative numbers, e.g. > > > 0 -8 0 0 8 Flashblock If it's under Windows, this is probably bug 1149897. If not, can you file a bug?

I believe that I have found an issue that could explain negative values and stuck add-ons. Bug 1150555.

(In reply to David Rajchenbach-Teller [:Yoric] (use "needinfo") from comment #169) > Surprising, but possible. I'd have to look at it. Can you file a bug > regarding this behavior wrt Menu Wizard and also a bug regarding this > behavior wrt Bugzilla Tweaks? Please file them in "Toolkit:Performance > Monitoring", Cc me and make sure that the platform information is correct. > (In reply to David Rajchenbach-Teller [:Yoric] (use "needinfo") from comment #171) > I believe that I have found an issue that could explain negative values and > stuck add-ons. Bug 1150555. So I guess Bug 1150555 is about this issue, right? > Addons appear only if they have had some activity during the past ~2 > seconds. Note that this is a very early design for about:performance, we > haven't even shown it to any ux person yet. If you have suggestions on how > to improve the design of about:performance, can you file them as new bugs in > component "Toolkit:Performance Monitoring"? > > Yes, that's the number of activations in the past ~2 seconds. So the fact that a number of addons stay suspiciously steadily at the top of the list with activations remaining at a similar value, is likely to be because of the bug? Most of them is doubtful to have been doing anything when the browser is idle and I'm watching about:performance. So 2 seconds... I imagined it would be some sort of counter for the whole session. I can't imagine this being useful for circumstances other than an addon constantly misbehaving without any sort of trigger, like getting in an infinite loop. But this is extremely rare. Or only the activations value is reset?

(In reply to avada from comment #172) > (In reply to David Rajchenbach-Teller [:Yoric] (use "needinfo") from comment > #171) > > I believe that I have found an issue that could explain negative values and > > stuck add-ons. Bug 1150555. > > So I guess Bug 1150555 is about this issue, right? Indeed. > > Yes, that's the number of activations in the past ~2 seconds. > > So the fact that a number of addons stay suspiciously steadily at the top of > the list with activations remaining at a similar value, is likely to be > because of the bug? Indeed. > So 2 seconds... I imagined it would be some sort of counter for the whole > session. We have a counter for the whole session, we just don't display it atm. In its current incarnation, about:performance is about being able to monitor what's going on at the moment. Module PerformanceStats.jsm offers all the information since the start of the process. > I can't imagine this being useful for circumstances other than an addon > constantly misbehaving without any sort of trigger, like getting in an > infinite loop. But this is extremely rare. If you have suggestions of better UX, please feel free to open bugs. I'm not a UX guy.

(In reply to David Rajchenbach-Teller [:Yoric] (use "needinfo") from comment #173) > We have a counter for the whole session, we just don't display it atm. In > its current incarnation, about:performance is about being able to monitor > what's going on at the moment. Module PerformanceStats.jsm offers all the > information since the start of the process. Dumb question: Where is this PerformanceStats.jsm and how do I make use of it? > If you have suggestions of better UX, please feel free to open bugs. I'm not > a UX guy. Yeah. Well I'm nothing so I can't really say much. It just makes more sense to me as a user to see a list of what's causing slowness in general instead of seeing what's happening now.

(In reply to avada from comment #174) > Dumb question: Where is this PerformanceStats.jsm and how do I make use of > it? https://dxr.mozilla.org/mozilla-central/source/toolkit/modules/PerformanceStats.jsm > Yeah. Well I'm nothing so I can't really say much. It just makes more sense > to me as a user to see a list of what's causing slowness in general instead > of seeing what's happening now. Doesn't mean that you can't file bugs.

It seems to be working as expected now. Addon numbers are reset every two seconds. And as such it's hard to derive any meaningful conclusions. (In reply to David Rajchenbach-Teller [:Yoric] (use "needinfo") from comment #175) > https://dxr.mozilla.org/mozilla-central/source/toolkit/modules/ > PerformanceStats.jsm > How do I make use of this file?