OO Plugin Api experiment Journal

This is the journal of the experiments performed that produced as result the PluginOOApi.

Benchmarking

I created 2 twiki installations : One base instalation to serve as a reference point for the benchmarks, and a OO instalation for the development.

The most representative script of the TWiki operation is the view script. In Cairo, it is basicaly 2 calls:

• a call to TWiki::initialize
• a call to TWiki::UI::View

I measured each call using the attached script and fixtures.

Time is the CPU time reported by the Benchmark module. 10 iteration where used. The average time is easily calculated (that's why I choose 10 iterations), so the total time of the 10 runs is shown.

The process (A Journal of Trial an Error)

Control Installation

Page	initialize	view	Total
Main.PerformanceBlankPage	2.33	2.39	4.73
Main.WebHome	2.40	3.50	5.90
Main.PerformanceTestPage	2.37	2.68	5.06
TWiki.GoodStyle	2.38	2.85	5.24
TWiki.TextFormattingRules	2.50	8.17	10.68
TWiki.DefaultPlugin	2.41	3.04	5.46

Control Instalation with All Plugins Disabled with $disableAllPlugins

Page	initialize	view	Total
Main.PerformanceBlankPage	0.51	1.88	2.39
Main.WebHome	0.50	2.74	3.24
Main.PerformanceTestPage	0.50	2.06	2.56
TWiki.GoodStyle	0.51	2.20	2.71
TWiki.TextFormattingRules	0.62	6.13	6.75
TWiki.DefaultPlugin	0.51	2.30	2.81

For the experiment, I'll change DefaultPlugin to the new OO way to handle plugins

Base Instalation with TWiki:Plugins.DefaultPlugin installed

I disabled all the other plugins using the DISABLEDPLUGINS preference

Page	initialize	view	Total
Main.PerformanceBlankPage	2.39	2.39	4.79
Main.WebHome	2.41	3.60	6.02
Main.PerformanceTestPage	2.45	2.70	5.15
TWiki.GoodStyle	2.37	2.87	5.25
TWiki.TextFormattingRules	2.47	7.93	10.40
TWiki.DefaultPlugin	2.36	3.11	5.47

Adds the new discovery and applyhandler mechanisms

Page	initialize	view	Total
Main.PerformanceBlankPage	2.42	2.40	4.83
Main.WebHome	2.39	3.53	5.92
Main.PerformanceTestPage	2.41	2.77	5.19
TWiki.GoodStyle	2.41	2.89	5.30
TWiki.TextFormattingRules	2.43	8.16	10.59
TWiki.DefaultPlugin	2.33	3.18	5.51

So, most of the initialization times went down, but the rendering process went up. Perhaps my original hypothesis (that calling the handlers all the time is faster than trying to discover which plugins can handle then) don't hold.

Change the TWiki:Plugins.DefaultPlugin to perform it's rendering on the commonTagsHandler

Page	initialize	view	Total
Main.PerformanceBlankPage	2.36	2.45	4.82
Main.WebHome	2.39	3.51	5.91
Main.PerformanceTestPage	2.42	2.72	5.14
TWiki.GoodStyle	2.39	2.87	5.27
TWiki.TextFormattingRules	2.50	8.07	10.58
TWiki.DefaultPlugin	2.32	3.14	5.47

OK... nearly the same result as the base case.

At this point I discovered that the proposed plugin handling is not reading the plugin preferences before calling init.

Reading plugin preferences before calling init

Page	initialize	view	Total
Main.PerformanceBlankPage	2.43	2.36	4.80
Main.WebHome	2.51	3.49	6.00
Main.PerformanceTestPage	2.48	2.73	5.22
TWiki.GoodStyle	2.45	2.82	5.28
TWiki.TextFormattingRules	2.58	7.88	10.47
TWiki.DefaultPlugin	2.48	3.03	5.52

This doesn't look good... What if we combine OO plugins with conditional execution?

Combine OO plugins with conditional execution

Note:This may sound weird, but Plugins::applyHandlers is being called 7 times before the plugins initialization. Further research is needed.

The idea is to call the plugin hook only is the plugin defined it. (using UNIVERSAL->can in Plugins::applyHandler).

Page	initialize	view	Total
Main.PerformanceBlankPage	2.48	2.41	4.90
Main.WebHome	2.51	3.48	5.99
Main.PerformanceTestPage	2.49	2.74	5.24
TWiki.GoodStyle	2.48	2.85	5.33
TWiki.TextFormattingRules	2.57	7.99	10.57
TWiki.DefaultPlugin	2.46	3.15	5.61

Combine OO plugins with conditional execution. Use AUTOLOAD to discard unknown calls

The idea is to use AUTOLOAD to ignore calls to undefined subs... which happened to be a very bad idea:

Page	initialize	view	Total
Main.PerformanceBlankPage	2.49	2.50	5.00
Main.WebHome	2.49	3.53	6.02
Main.PerformanceTestPage	2.57	2.79	5.37
TWiki.GoodStyle	2.49	2.93	5.42
TWiki.TextFormattingRules	2.62	8.15	10.78
TWiki.DefaultPlugin	2.51	3.11	5.63

Combine OO plugins with traditional conditional execution

This mean, execute only those handlers defined by the plugin. After test...

Bingo! The wisdom of the old TWIKI-sages is infinite. The numbers are mostly the same as the base test:

Page	initialize	view	Total
Main.PerformanceBlankPage	2.39	2.38	4.78
Main.WebHome	2.43	3.47	5.91
Main.PerformanceTestPage	2.36	2.75	5.12
TWiki.GoodStyle	2.36	2.87	5.24
TWiki.TextFormattingRules	2.52	7.85	10.38
TWiki.DefaultPlugin	2.44	2.98	5.43

So far, to provide a OO interface for plugins seems to be a viable idea.

Note: In all the test, the code for original-styled plugins is there, so it's really performing initialization for original-style and oo-style.

Verifying that both mechanism can coexist in the same instalation

Let's try to use the new DefaultPlugin with a traditional plugin. I choose the TWiki:Plugins.TablePlugin because it is commonly used.

For this test, I renamed all the plugins .pm modules except TWiki:Plugins.DefaultPlugin and TWiki:Plugins.TablePlugin in both my control and experimental installations. The numbers are quite revealing:

(Control) Base Installation with DefaultPlugin and TablePlugin

Page	initialize	view	Total
Main.PerformanceBlankPage	0.72	1.98	2.70
Main.WebHome	0.75	2.91	3.66
Main.PerformanceTestPage	0.75	2.21	2.96
TWiki.GoodStyle	0.76	2.34	3.10
TWiki.TextFormattingRules	0.84	6.84	7.68
TWiki.DefaultPlugin	0.76	2.60	3.36
TWiki.TablePlugin	0.84	5.58	6.42

It's commonly known that the TWiki performance decreases as the number of plugins increases, but I expected this increase to be mostly in the view part, but as it happens the view time increase ranges 17~22%, but initialization time increase is 200~230%!!! And thats only for 8 additional plugins. (these are Cairo numbers).

Let me reparaphrase that: With 8 plugins installed, using the DISABLEDPLUGINS preference, the initialization time for plugis was about 0.240 secs per call (2.40 secs for 10 calls), but uninstalling 6 of those plugins gives an initialization time of 0.077 secs per call!

Well... that said, let's go back to the experiment at hand.

Experimental Installation with DefaultPlugin and TablePlugin

Something weird is happening, the TablePlugin is active in the experimental instalation, but is not being listed in the Active Plugins list in TWikiPreferences. The problem is in this code:

     push  @activePlugins, $plugin if not grep $plugin,@activePlugins;

@activePlugins only has the value "(DefaultPlugin)", $plugin has the value "TablePlugin",but the grep returns true (so, the whole if is false).

Anyway, these are the numbers:

Page	initialize	view	Total
Main.PerformanceBlankPage	0.70	2.07	2.77
Main.WebHome	0.78	2.88	3.66
Main.PerformanceTestPage	0.76	2.26	3.02
TWiki.GoodStyle	0.78	2.35	3.13
TWiki.TextFormattingRules	0.84	6.81	7.65
TWiki.DefaultPlugin	0.75	2.59	3.34
TWiki.TablePlugin	0.83	5.57	6.40

So, both methods can coexist without performance penalty.

Futher study is needed to test how the performance is impacted by adding another plugin of each kind (00 and traditional)

Change the user handling (earlyInitPlugin) of OO plugins

A piece of code was left out: the earliInitPlugin stuff if the user is not specified.

Page	initialize	view	Total
Main.PerformanceBlankPage	0.75	2.04	2.79
Main.WebHome	0.74	2.90	3.64
Main.PerformanceTestPage	0.78	2.22	3.00
TWiki.GoodStyle	0.74	2.39	3.13
TWiki.TextFormattingRules	0.86	6.78	7.63
TWiki.DefaultPlugin	0.75	2.59	3.34
TWiki.TablePlugin	0.89	5.64	6.53

New Day: Provide some services to plugins via PluginSkel

To start fresh, let's run the bechmark for the control installation:

Page	initialize	view	Total
Main.PerformanceBlankPage	0.76	1.98	2.74
Main.WebHome	0.74	2.91	3.65
Main.PerformanceTestPage	0.77	2.23	3.00
TWiki.GoodStyle	0.76	2.35	3.11
TWiki.TextFormattingRules	0.87	6.80	7.67
TWiki.DefaultPlugin	0.74	2.59	3.33
TWiki.TablePlugin	0.88	5.50	6.38

Provide the plugin preferences as "instance fields"

To test this, 10 calls to the writeDebug sub using the "debug" preference were inserted in the commonTagsHandler handler

Page	initialize	view	Total
Main.PerformanceBlankPage	0.74	3.43	4.17
Main.WebHome	0.78	5.34	6.12
Main.PerformanceTestPage	0.75	3.73	4.48
TWiki.GoodStyle	0.76	3.88	4.65
TWiki.TextFormattingRules	0.84	8.30	9.14
TWiki.DefaultPlugin	0.74	4.08	4.82
TWiki.TablePlugin	0.82	7.06	7.88

Wow! I didn't expect the overhead to be this much :S

But WAIT! The debug preference was ON during this test, and during the base test it was "off"... A rerun of the benchmark results in

Page	initialize	view	Total
Main.PerformanceBlankPage	0.75	2.30	3.05
Main.WebHome	0.72	3.39	4.11
Main.PerformanceTestPage	0.79	2.57	3.36
TWiki.GoodStyle	0.78	2.69	3.47
TWiki.TextFormattingRules	0.87	7.24	8.11
TWiki.DefaultPlugin	0.78	2.84	3.62
TWiki.TablePlugin	0.81	5.89	6.70

Ok... this is "better", in the sense that's the overhead somethig I would expect.

I should have know this as the previous experiment with AUTOLOAD gave me abysmal results.

Init the debug preferences in the initPlugin sub

Page	initialize	view	Total
Main.PerformanceBlankPage	0.76	2.05	2.81
Main.WebHome	0.74	2.97	3.71
Main.PerformanceTestPage	0.73	2.31	3.04
TWiki.GoodStyle	0.77	2.41	3.18
TWiki.TextFormattingRules	0.89	6.91	7.80
TWiki.DefaultPlugin	0.78	2.58	3.36
TWiki.TablePlugin	0.85	5.63	6.48

Just out of curiosity, I commented the calls to writeDebug. The numbers:

Page	initialize	view	Total
Main.PerformanceBlankPage	0.76	2.00	2.76
Main.WebHome	0.75	2.93	3.68
Main.PerformanceTestPage	0.76	2.25	3.01
TWiki.GoodStyle	0.74	2.36	3.10
TWiki.TextFormattingRules	0.85	6.79	7.64
TWiki.DefaultPlugin	0.76	2.55	3.31
TWiki.TablePlugin	0.83	5.57	6.40

And changed the call from $self->writeDebug to TWiki::Func::writeDebug if $debug

Page	initialize	view	Total
Main.PerformanceBlankPage	0.78	2.02	2.80
Main.WebHome	0.76	2.89	3.65
Main.PerformanceTestPage	0.73	2.29	3.02
TWiki.GoodStyle	0.76	2.35	3.11
TWiki.TextFormattingRules	0.86	6.82	7.68
TWiki.DefaultPlugin	0.77	2.51	3.28
TWiki.TablePlugin	0.84	5.54	6.38

hmmm... there is an apreciable slowdown....

Let's see how it behaves accessing the other preference in DefaultPlugin. To check that, both the control version and the new version of DefaultPlugin will be modified to access 10 times the OLDINCLUDE preference in the commonTagsHandler. Note: The calls to writeDebug are still in place

Access the other preference, control installation

Page	initialize	view	Total
Main.PerformanceBlankPage	0.71	2.03	2.74
Main.WebHome	0.73	3.02	3.75
Main.PerformanceTestPage	0.77	2.23	3.00
TWiki.GoodStyle	0.78	2.40	3.18
TWiki.TextFormattingRules	0.84	6.93	7.77
TWiki.DefaultPlugin	0.77	2.63	3.40
TWiki.TablePlugin	0.84	5.60	6.44

Access the other preference, OO version

Page	initialize	view	Total
Main.PerformanceBlankPage	0.74	2.23	2.97
Main.WebHome	0.74	3.27	4.01
Main.PerformanceTestPage	0.77	2.47	3.24
TWiki.GoodStyle	0.76	2.56	3.33
TWiki.TextFormattingRules	0.87	6.97	7.84
TWiki.DefaultPlugin	0.73	2.80	3.53
TWiki.TablePlugin	0.82	5.77	6.59

WOW, now that's a big difference! Why is this happening?

DPRofing a run with 5 iterations, I found out that TWiki::Plugins::PluginSkel::getPreferencesValue is being called 660 times for a total of 0.067 sec. In the control instalation, Func::getPluginPreferencesValue is being called 222 times for a total of 0.014 sec. Now, this is interesting: getPluginPreferencesValue is being called from the plugin more than 3 times than the total calls from the control installation.I just can find why

Just to check, I replaced the calls to the base plugin to calls to the Func module. These are the numbers:

Page	initialize	view	Total
Main.PerformanceBlankPage	0.71	2.38	3.09
Main.WebHome	0.72	3.51	4.24
Main.PerformanceTestPage	0.75	2.60	3.35
TWiki.GoodStyle	0.74	2.72	3.46
TWiki.TextFormattingRules	0.85	7.20	8.05
TWiki.DefaultPlugin	0.77	2.89	3.66
TWiki.TablePlugin	0.82	5.88	6.70

What?! They are SLOWER!

Well, I guess that I'll leave the OO way to access preferences.

Clean up for the next feature

Now, I'll remove unnecessary access to preferences in both plugins, and check where we are in terms of performance:

Control Installation

Page	initialize	view	Total
Main.PerformanceBlankPage	0.73	1.97	2.70
Main.WebHome	0.75	2.91	3.66
Main.PerformanceTestPage	0.75	2.20	2.95
TWiki.GoodStyle	0.74	2.35	3.09
TWiki.TextFormattingRules	0.85	6.85	7.70
TWiki.DefaultPlugin	0.76	2.57	3.33
TWiki.TablePlugin	0.82	5.53	6.35

OO Installation

Page	initialize	view	Total
Main.PerformanceBlankPage	0.75	2.05	2.80
Main.WebHome	0.77	2.90	3.67
Main.PerformanceTestPage	0.75	2.26	3.01
TWiki.GoodStyle	0.74	2.38	3.12
TWiki.TextFormattingRules	0.86	6.79	7.65
TWiki.DefaultPlugin	0.77	2.57	3.34
TWiki.TablePlugin	0.83	5.55	6.38

Ok, now onto the next feature

Discovery

Found a critical flaw that was affecting the benchmarks. Each time Plugins::initialize1 was called, all the OO handlers where added again, so each run the handler was called one more time than the last (that explains the 660 calls to PluginSkel::getPreferencesValue). Silly me. These are the right numbers:

Control Installation

Page	initialize	view	Total
Main.PerformanceBlankPage	0.75	1.97	2.72
Main.WebHome	0.76	3.06	3.82
Main.PerformanceTestPage	0.72	2.22	2.94
TWiki.GoodStyle	0.71	2.39	3.10
TWiki.TextFormattingRules	0.84	6.94	7.78
TWiki.DefaultPlugin	0.79	2.66	3.46
TWiki.TablePlugin	0.86	5.62	6.48

OO Installation

Page	initialize	view	Total
Main.PerformanceBlankPage	0.76	2.04	2.80
Main.WebHome	0.75	2.87	3.62
Main.PerformanceTestPage	0.75	2.27	3.02
TWiki.GoodStyle	0.76	2.33	3.09
TWiki.TextFormattingRules	0.85	6.79	7.64
TWiki.DefaultPlugin	0.74	2.55	3.29
TWiki.TablePlugin	0.82	5.52	6.34

Convert TWiki::Plugins.TablePlugin to the pure OO way

I'll convert TWiki::Plugins.TablePlugin to use the base TWiki::Plugins.PluginSkel, completing the TWiki::Plugins.PluginSkel implementation with anything needed in the way. After that, we could compare the plugins in the control installation with a pure OO instalation and check the performance impact.

First Step: Make TWiki::Plugins.TablePlugin a OO plugin

Without further modifications, just add the @ISA and change the handlers to receive $self:

Page	initialize	view	Total
Main.PerformanceBlankPage	0.79	1.97	2.76
Main.WebHome	0.79	2.87	3.66
Main.PerformanceTestPage	0.74	2.24	2.98
TWiki.GoodStyle	0.75	2.36	3.11
TWiki.TextFormattingRules	0.90	6.71	7.61
TWiki.DefaultPlugin	0.77	2.51	3.28
TWiki.TablePlugin	0.86	5.50	6.36

looks promising

New Day: Complete Conversion of TablePlugin

This mean that every call to TWiki::Func was replaced with a call to a sub in PluginSkel using $self->

Again, new day == new bench

Control installation

Page	initialize	view	Total
Main.PerformanceBlankPage	0.73	1.98	2.71
Main.WebHome	0.75	2.91	3.67
Main.PerformanceTestPage	0.75	2.22	2.97
TWiki.GoodStyle	0.77	2.37	3.14
TWiki.TextFormattingRules	0.82	6.90	7.72
TWiki.DefaultPlugin	0.75	2.59	3.34
TWiki.TablePlugin	0.78	5.57	6.35

OO Installation

Page	initialize	view	Total
Main.PerformanceBlankPage	0.75	2.01	2.76
Main.WebHome	0.76	2.92	3.67
Main.PerformanceTestPage	0.77	2.25	3.02
TWiki.GoodStyle	0.74	2.37	3.11
TWiki.TextFormattingRules	0.90	6.74	7.64
TWiki.DefaultPlugin	0.78	2.53	3.31
TWiki.TablePlugin	0.86	5.52	6.38

hmm.. there is a (minimal) performance gain in pages that actually use the plugin, and a (minimal) performance loss in those that don't.

-- RafaelAlvarez - 08 Sep 2004

Comments