412770 - Add ability to monitor plug-ins at run-time

Status: RESOLVED FIXED

(Core Graveyard :: Plug-ins, enhancement)

Description

[Fima Kachinski]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.11) Gecko/20071127 Firefox/2.0.0.11
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9a9pre) Gecko/2007100519 Minefield/3.0a9pre

This is the preliminary release of Plugin Watcher which is a project I have been working on as part of the open source development course at Seneca college. The project's purpose is to track the runtime given to plugins within Firefox and alert the user if it exceeds the normal range. It currently only runs on Windows and Linux - no OSX support yet, but it is in the works. 

I'm posting the patch here in the hopes of getting a lot of feedback - so if you have any comments about the code or suggestions on possible improvements I would appreciate hearing from you.

Some general patch information:
There are two parts to PW, the C++ part located inside "nsPluginSafety.h" (/mozilla/modules/plugin/base/src) and the Javascript part, currently located inside "browser.js" (/mozilla/browser/base/content). The C++ part works by sending the runtime of the plugin using the observer service and the JS part works by utilizing that data to determine when and how to alert the user. I plan on taking the JS part out of "browser.js" and implementing it as an extension instead. I also plan on making some changes to the C++ code and I'm hoping that your suggestions will point me in the right direction.

As mentioned before, your suggestions, comments, general feedback or criticism is welcome and appreciated!

Reproducible: Always




For more information you are welcome to visit my blog and/or the PW wiki project page:
http://xrayon.blogspot.com/
http://zenit.senecac.on.ca/wiki/index.php/Plugin-watcher

Comment 1

[Fima Kachinski]

Attachment: Plugin Watcher 0.31 patch -- works on Linux and Windows only at the moment

Comment 2

[Fima Kachinski]

Attachment: The JS side of PW has been moved to an extension, this is the patch for the C++ portion.

Comment 3

[Fima Kachinski]

Attachment: The Plugin Watcher extension.

This is the Plugin Watcher extension portion where all the front end JS code has been moved to.

Comment 4

[Robert O'Callahan (:roc) (email my personal email if necessary)]

You can shrink this code a few ways. The main thing is to put all the code that happens after the call to "fun" in a helper function that can be shared. Also, the call to ticksPerSecond can be moved way down until you really need it.

If you want to land this you'll need to get rid of those printfs or change them to PR_LOG. You don't want to spew on the console of millions of people :-).

Somewhere we'll need some documentation of your observer notifications --- when they fire, what they mean. "PluginWatcher" probably isn't a good name for the notification. Maybe "notify-plugin-call"?

We might need to look at peformance issues, this path is potentially called quite a bit in some Web pages. A good experiment would be to create a test page that makes trivial calls into a Flash object from Javascript (examples of this abound on the Web), put a lot of those calls into a tight loop and test with and without your code to see if your code makes a difference to the running time.

Comment 5

[Fima Kachinski]

Attachment: PW v0.8

This release implements the technical changes proposed by Robert in his review of the code. The repeating code has been moved into a separate macro, the ticksPerSecond call was moved to the appropriate location, the notification subject has been changed to "notify-plugin-call", the printfs have been eliminated and the code was shortened by the removal of an unnecessary evaluation. Some comments have also been inserted into the code, however those may need to be expanded.

Comment 6

[Fima Kachinski]

Attachment: The PW Extension v0.8

This extension is designed to work with the new C++ code in the v0.8 patch while also adding a new recording feature - allowing users to capture plugin run time to a file.

Comment 7

[Robert O'Callahan (:roc) (email my personal email if necessary)]

+//This MACRO sends a notification using the observer service to any object registered to listen to the "notify-plugin-call" subject.
+//Each "notify-plugin-call" notification carries with it the run time value in milliseconds that the call took to execute.
+#define NOTIFY_PLUGIN_CALL(startTime)  										\
+PR_BEGIN_MACRO																\
+    PRIntervalTime endTime = (PRIntervalTime)PR_IntervalNow() - startTime;	\
+	nsCOMPtr<nsIObserverService> notifyUIService =							\
+		do_GetService("@mozilla.org/observer-service;1");					\
+	float runTimeRatio = (float) endTime / PR_TicksPerSecond();				\
+	nsString runTimeString;													\
+	runTimeString.AppendFloat(runTimeRatio);								\
+	const PRUnichar* runTime = runTimeString.get();							\
+	notifyUIService->NotifyObservers(nsnull, "notify-plugin-call", runTime);\
+PR_END_MACRO

This is a macro, not a function. Functions allow code to be shared, macros really don't.

Have you been able to do any performance tests?

Comment 8

[Fima Kachinski]

Attachment: PW v0.81

Robert, the code has now been moved into a function, the definition for which resides in a new file (nsNotifyPluginCall.cpp). As for the testing you proposed, I am making it my next priority. One of the things I am a little unsure of is how to compare the two cases (running with PW and without), I would appreciate it if you could put me in the right direction. I'm hoping to get it done by the end of next week (latest).

Comment 9

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Is there no existing file where it would make sense to add this function?

+void notifyPluginCall(PRIntervalTime startTime) { 										
+    PRIntervalTime endTime = (PRIntervalTime)PR_IntervalNow() - startTime;	
+	nsCOMPtr<nsIObserverService> notifyUIService =							
+								 do_GetService("@mozilla.org/observer-service;1");	
+	float runTimeRatio = (float) endTime / PR_TicksPerSecond();				
+	nsString runTimeString;													
+	runTimeString.AppendFloat(runTimeRatio);								
+	const PRUnichar* runTime = runTimeString.get();							
+	notifyUIService->NotifyObservers(nsnull, "notify-plugin-call", runTime);
+}

Your indent is all wonky.

runTimeString should be an nsAutoString so that the text is stack-allocated instead of heap-allocated

notifyPluginCall should be named NS_NotifyPluginCall to avoid polluting the namespace.

+void notifyPluginCall(PRIntervalTime);

Why not just hoist this outside the #ifdef so you don't have to repeat it?

You might find that caching the observer service reference so you don't have to call do_GetService all the time is a pref win, but we'll see...

For testing you need to create a testcase that does a lot of calls into plugins. One way would be to create a Flash object that exposes a scriptable API and then call that API many times from JS in the page in a loop ... you can probably find demos of this on the Web. The JS in the page would use JS Date objects to time how long it takes for the test to run. Does that make sense?

Comment 10

[Fima Kachinski]

Attachment: PW v0.82

"Is there no existing file where it would make sense to add this function?"

Done -- moved the function to ns4xPlugin.cpp... seems like the most logical place for it.

"Your indent is all wonky."

Fixed.

"runTimeString should be an nsAutoString so that the text is stack-allocated
instead of heap-allocated"

Done.

"notifyPluginCall should be named NS_NotifyPluginCall to avoid polluting the
namespace."

Done.

"+void notifyPluginCall(PRIntervalTime);

Why not just hoist this outside the #ifdef so you don't have to repeat it?"

Done.

"You might find that caching the observer service reference so you don't have to
call do_GetService all the time is a pref win, but we'll see..."

As we discussed I'm leaving this off for now. Regarding the performance testing, it is still in the works. I will post test data here as soon as its available.

Comment 11

[Robert O'Callahan (:roc) (email my personal email if necessary)]

+  PRIntervalTime endTime = (PRIntervalTime)PR_IntervalNow() - startTime;

Why is this cast needed?

+  float runTimeRatio = (float) endTime / PR_TicksPerSecond();

This is just the time in seconds so 'runTimeRatio' is not a very good name.

+  float runTimeRatio = (float) endTime / PR_TicksPerSecond();

Use C++ casts when possible; in this case, a constructor-style cast.

Otherwise looks good.

Comment 12

[Fima Kachinski]

Attachment: PW Extension v0.9

Version 0.9 of the PW Extension has a number of significant changes. Visually there is now a graphical representation of the plugin load on the bottom right corner of the browser as well as an on/off indicator. The notification method has also changed, the code has been cleaned and substantially shortened and the plugin recorder feature has been removed - posibly to be implemented as a seperate extension if there is a demand for it. A few small bugs have also been fixed in this release.

Comment 13

[Fima Kachinski]

Comment on attachment 312875 [details]
PW Extension v0.9

I have a blog post detailing the new extension features with some screen shots... http://xrayon.blogspot.com/2008/04/demo-2-and-pw-extension-v09-screenshots.html

Comment 14

[Fima Kachinski]

Attachment: PW Core Patch v0.9

"+  PRIntervalTime endTime = (PRIntervalTime)PR_IntervalNow() - startTime;

Why is this cast needed?"

- Its not. Fixed.


"+  float runTimeRatio = (float) endTime / PR_TicksPerSecond();

This is just the time in seconds so 'runTimeRatio' is not a very good name."

- Changed to runTimeInSeconds.


"+  float runTimeRatio = (float) endTime / PR_TicksPerSecond();

Use C++ casts when possible; in this case, a constructor-style cast."

- Changed to a constructor style cast (float(endTime)).

Comment 15

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Comment on attachment 315739 [details] [diff] [review]
PW Core Patch v0.9

looks good.

Comment 16

[Fima Kachinski]

For the performance testing of PW, I have created a short Flash clip that
exposes an Actionscript function that can be called from JavaScript. I have
also created a web page that incorporates this clip and a button that when
pressed initiates a loop where that function is called many times (currently
set to 10000). Once the loop executes it provides information on how long the
loop took to execute. Since the loop always runs the same function with the
same data, a comparison can be made by running it on a browser with PW turned
on and off. 

Here is the link to the performance test: 
http://matrix.senecac.on.ca/~ekachins/pwJSTest/pwPerfTester.html

I will also be shortly posting some results from the tests that I have run so
far on my blog at: 
http://xrayon.blogspot.com

Comment 17

[Fima Kachinski]

Comment on attachment 315739 [details] [diff] [review]
PW Core Patch v0.9

This patch adds functionality that measures a running plugin's performance and allows a user to gauge how it is affecting page and overall application performance. This can also help solve tricky plugin performance issues and allow live chat support staff to actually help people with plugin issues and allow for a better diagnoses of the underlying problem.

Comment 18

[Fima Kachinski]

This is a continuation from the last comment:

Risk analysis -
Since the code this patch introduces does not alter the existing plugin
infrastructure but merely adds a simple mechanism that allows for the timing of
each plugin call, I believe it is relatively safe to introduce it into the
tree.

Performance testing of PW core patch -

This table depicts the run time in milliseconds (as measured using JS Date
objects) of JS calls into an exposed Actionscript function within an embedded
Flash clip. This function is run 10,000 times in a loop for each individual
test.

        PW ON   PW OFF
Test 1  3249    3260
Test 2  3423    3427
Test 3  3269    3233
Test 4  3243    3237
Test 5  3248    3226
Test 6  3257    3204
Test 7  3238    3270
Test 8  3264    3297
Test 9  3266    3241
Test 10 3247    3245
Average 3270.4  3264

You can also see this in a graph here:
http://tinyurl.com/5e4eed

The results seem to suggest that whatever difference is made by the PW code, it
is drowning in the noise and does not produce any noticeable impact.

Comment 19

[Robert O'Callahan (:roc) (email my personal email if necessary)]

What does that Actionscript function do when you call it? For a good test here, it should really be doing nothing, and nothing else should be going on. When I look at the test there's some animation, but we don't really want that to be part of the test.

Comment 20

[Fima Kachinski]

(In reply to comment #19)
> What does that Actionscript function do when you call it? For a good test here,
> it should really be doing nothing, and nothing else should be going on. When I
> look at the test there's some animation, but we don't really want that to be
> part of the test.
> 

The Actionscript function is below:

function startTest(num1, num2) {
	
	for (num2; num2 > 0; num2--) {
		num1 = num1 * num1;
	}
	
	return num1;
}

Its rather basic, but it is still doing something. Should I reduce whatever its doing further?

The animation is there for entertainment purposes only :). I would be happy to remove it if that helps too.

Comment 21

[Mike Shaver (:shaver -- probably not reading bugmail closely)]

Yeah, it should just return its first parameter, and disable the animation.  You might also use Date.now() instead of |new Date()| to get lower overhead in the timing.

Comment 22

[Fima Kachinski]

(In reply to comment #21)
> Yeah, it should just return its first parameter, and disable the animation. 
> You might also use Date.now() instead of |new Date()| to get lower overhead in
> the timing.
> 

The function now just returns the first argument, the animation has been taken off and it is now using Date.now() instead of new Date(). I also cleaned the JS a bit. 

The URL is the same:
http://matrix.senecac.on.ca/~ekachins/pwJSTest/pwPerfTester.html

In the process of doing a fresh build to test it out. Will post the results here when finished.

Comment 23

[Fima Kachinski]

So I have performed some additional testing - this time with the revised clip and some additional modifications to the page JavaScript code. 

I added a button to the test page that runs 10 consecutive tests in a row - this eliminates the need to manually press the test button 10 times. Hopefully this will also make it more consistent across runs.

Here is the result from test run number I
	PW ON	PW OFF
Test 1	3135	3174
Test 2	3144	3156
Test 3	3139	3130
Test 4	3140	3175
Test 5	3161	3135
Test 6	3144	3153
Test 7	3156	3173
Test 8	3154	3139
Test 9	3146	3165
Test 10	3153	3154
Average	3147.2	3155.4

Test number one was run on minefield 3.0pre, with PW OFF running first.

And here is the result from test run number II
	PW ON	PW OFF
Test 1	3176	3142
Test 2	3399	3160
Test 3	3197	3137
Test 4	3142	3159
Test 5	3155	3137
Test 6	3172	3141
Test 7	3152	3167
Test 8	3177	3148
Test 9	3166	3148
Test 10	3165	3162
Average	3190.1	3150.1

Test number two was also run on minefield 3.0pre, with PW ON running first.

Comment 24

[Robert O'Callahan (:roc) (email my personal email if necessary)]

That looks good.

Comment 25

[Fima Kachinski]

Posted some screen shots related to the above testing on my blog:
http://xrayon.blogspot.com/2008/04/what-day.html

Comment 26

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

One suggestion -- instead of doing the current amount of work in NotifyPluginCall, I would suggest the following:

- Create a new XPCOM interface, nsIPluginWatcher or something.  It should have a single method, "void notifyCall(in long callLength);".
- The plugin watcher extension should implement this interface, as a service, under something like "@mozilla.org/plugin-watcher;1"
- ns4xPlugin.cpp should do_getService on that contractid once and store the result in some global spot (maybe on the first plugin construction)
- then if that service exists, it should just call NotifyCall on it with the time in ms.

I know that there isn't a noticable performance issue with the particular testcase given, but there's still a lot of work being done, and I think that work should be reduced as much as possible.

Comment 27

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

(In reply to comment #25)
> Posted some screen shots related to the above testing on my blog:
> http://xrayon.blogspot.com/2008/04/what-day.html

Ack, say no to charts that have a y axis that doesn't start at 0!  Those charts actually look much worse than the data that they represent :)

Comment 28

[Mike Shaver (:shaver -- probably not reading bugmail closely)]

(In reply to comment #26)
> One suggestion -- instead of doing the current amount of work in
> NotifyPluginCall, I would suggest the following:
> 
> - Create a new XPCOM interface, nsIPluginWatcher or something.  It should have
> a single method, "void notifyCall(in long callLength);".
> - The plugin watcher extension should implement this interface, as a service,
> under something like "@mozilla.org/plugin-watcher;1"
> - ns4xPlugin.cpp should do_getService on that contractid once and store the
> result in some global spot (maybe on the first plugin construction)
> - then if that service exists, it should just call NotifyCall on it with the
> time in ms.
> 
> I know that there isn't a noticable performance issue with the particular
> testcase given, but there's still a lot of work being done, and I think that
> work should be reduced as much as possible.

I disagree; testing shows that the overhead is minimal (though it'd be great to hear about other cases to test -- is this macro only used in the scriptable-call case? do we wrap painting calls in this?), and inventing a new lifecycle pattern in ns4xPlugin code is a great way to turn a simple and easy-to-reason-about patch into a nightmare.  We shouldn't take significant complexity for trivial performance improvements, especially in code that has enough strange lifecycle stuff in it already.

Singleton pigeonholing sucks, and our story for selecting which contract implementation is used sucks more, so I think we should avoid bespoke elements here.

Comment 29

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Painting goes through here for windowless plugins. However, I very much hope that a single scripted null call is far cheaper than a paint.

Comment 30

[Mike Beltzner [:beltzner, not reading bugmail]]

Comment on attachment 315739 [details] [diff] [review]
PW Core Patch v0.9

Shaver and Vlad are now agreed that we should take this patch with "experimental-" at the beginning, and if there are any perf impacts noticeable -- perhaps because Dell ships a laptop with hardware acceleration for XPConnect? -- we can tear it out with abandon in a .0.x, or rev it mercilessly in .next to add plugin context or filtering of the sample rate or RTL support.

Can we get the API change made?

Comment 31

[Fima Kachinski]

Attachment: PW Core Patch v0.91

This patch adds the "experimental-" prefix to the topic.

Comment 32

[Fima Kachinski]

(In reply to comment #27)
> (In reply to comment #25)
> > Posted some screen shots related to the above testing on my blog:
> > http://xrayon.blogspot.com/2008/04/what-day.html
> 
> Ack, say no to charts that have a y axis that doesn't start at 0!  Those charts
> actually look much worse than the data that they represent :)
> 

Hey Vlad, thanks for pointing this out :). I have new graphs posted on my blog 
http://xrayon.blogspot.com/2008/04/patch-going-experimental.html

Comment 33

[Fima Kachinski]

Attachment: PW Extension v0.91

Changes since 0.9:

- The extension can now be enabled/disabled directly from the status bar icon.
- A new popup notification appears above the status bar meter if a consistent high run time is detected.
- The extension now listens for the new "experimental-notify-plugin-call" topic name

Comment 34

[Mike Beltzner [:beltzner, not reading bugmail]]

Comment on attachment 315925 [details] [diff] [review]
PW Core Patch v0.91

a1.9=beltzner

Comment 35

[:Gijs (he/him)]

Comment on attachment 315925 [details] [diff] [review]
PW Core Patch v0.91

Carrying over roc's r+sr per comments and approval and such. Fima doesn't have checkin privileges, so it would be cool if someone could check this in as soon as qm-xserve01 has calmed down a bit. Thanks!

Comment 36

[Robert O'Callahan (:roc) (email my personal email if necessary)]

One additional thing we really need here is some kind of mochitest to ensure this keeps working.

Comment 37

[Mike Shaver (:shaver -- probably not reading bugmail closely)]

Yep -- when we get a test plugin in the tree, it should be pretty straightforward.  Maybe Fima's next project. :)

Comment 38

[Reed Loden [:reed]]

Comment on attachment 315925 [details] [diff] [review]
PW Core Patch v0.91

No need to carry review flags over... This just confuses people.

Comment 39

[Fima Kachinski]

Attachment: PW extension v1.0

- Fixed multiple listener registration bug.
- Changed all new Date() to Date.now().

Will be posting it to addons.mozilla.org as well.

Comment 40

[Johnny Stenback (:jst)]

Comment on attachment 315925 [details] [diff] [review]
PW Core Patch v0.91

+//This function sends a notification using the observer service to any object registered to listen to the "experimental-notify-plugin-call" subject.
+//Each "experimental-notify-plugin-call" notification carries with it the run time value in milliseconds that the call took to execute.

Please wrap this comment (and other changes in this patch as well) to fit in 80 columns.

sr=jst too fwiw.

Comment 41

[:Gavin Sharp [email: [e-mail]]]

mozilla/modules/plugin/base/src/ns4xPlugin.cpp 	1.164
mozilla/modules/plugin/base/src/nsPluginSafety.h 	1.15

Comment 42

[:Gavin Sharp [email: [e-mail]]]

Attachment: wrapping followup

Oops, I forgot to address jst's nit on checkin. Landed this as a followup.