%META:TOPICINFO{author="guest" date="1094530526" format="1.0" version="1.1"}%

---+Introducing the OO style plugins

As shown in another topic (look for it), could be very practical to have a common Base plugin and make new plugins to extends from this base plugin. This could remove the need for the TWiki::Func module altogether, or at least put all the code referencing it in one place. Also it can make initiatives like the TWiki::Plugins.CodeContribution easier to do (every common stuff will be in the base plugin, for example). 

So, this research has 2 focus:
	* To provide a OO framework for plugins.
	* Keep the performance at least as good as Cairo.

---++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.

---+++Pages used for testing:

	* PerformanceTestPage
	* PerformanceBlankPage
	* Main.WebHome
	* TWiki.GoodStyle
	* TWiki.TextFormatingRules
	* TWiki.DefaultPlugin
	* TWiki.TablePlugin

---++ The process (A Journal of Trial an Error)


---+++(Control) Base Installation 
|*Page*|*initialize*|*view*|*Total*|
| <nop>Main.PerformanceBlankPage |2.33|2.39|4.73|
| <nop>Main.WebHome |2.40|3.50|5.90|
| <nop>Main.PerformanceTestPage |2.37|2.68|5.06|
| <nop>TWiki.GoodStyle |2.38|2.85|5.24|
| <nop>TWiki.TextFormattingRules |2.50|8.17|10.68|
| <nop>TWiki.DefaultPlugin |2.41|3.04|5.46|

---+++(Control) BaseInstalation with All Plugins Disabled with <nop>$disableAllPlugins

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

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

---+++BaseInstalation with DefaultPlugin installed

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

---+++Adds the new discovery and applyhandler mechanisms

|*Page*|*initialize*|*view*|*Total*|
| <nop>Main.PerformanceBlankPage |2.42|2.40|4.83|
| <nop>Main.WebHome |2.39|3.53|5.92|
| <nop>Main.PerformanceTestPage |2.41|2.77|5.19|
| <nop>TWiki.GoodStyle |2.41|2.89|5.30|
| <nop>TWiki.TextFormattingRules |2.43|8.16|10.59|
| <nop>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 DefaultPlugin to perform it's rendering on the commonTagsHandler

|*Page*|*initialize*|*view*|*Total*|
| <nop>Main.PerformanceBlankPage |2.36|2.45|4.82|
| <nop>Main.WebHome |2.39|3.51|5.91|
| <nop>Main.PerformanceTestPage |2.42|2.72|5.14|
| <nop>TWiki.GoodStyle |2.39|2.87|5.27|
| <nop>TWiki.TextFormattingRules |2.50|8.07|10.58|
| <nop>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*|
| <nop>Main.PerformanceBlankPage |2.43|2.36|4.80|
| <nop>Main.WebHome |2.51|3.49|6.00|
| <nop>Main.PerformanceTestPage |2.48|2.73|5.22|
| <nop>TWiki.GoodStyle |2.45|2.82|5.28|
| <nop>TWiki.TextFormattingRules |2.58|7.88|10.47|
| <nop>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*|
| <nop>Main.PerformanceBlankPage |2.48|2.41|4.90|
| <nop>Main.WebHome |2.51|3.48|5.99|
| <nop>Main.PerformanceTestPage |2.49|2.74|5.24|
| <nop>TWiki.GoodStyle |2.48|2.85|5.33|
| <nop>TWiki.TextFormattingRules |2.57|7.99|10.57|
| <nop>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*|
| <nop>Main.PerformanceBlankPage |2.49|2.50|5.00|
| <nop>Main.WebHome |2.49|3.53|6.02|
| <nop>Main.PerformanceTestPage |2.57|2.79|5.37|
| <nop>TWiki.GoodStyle |2.49|2.93|5.42|
| <nop>TWiki.TextFormattingRules |2.62|8.15|10.78|
| <nop>TWiki.DefaultPlugin |2.51|3.11|5.63|

---+++ Combine OO plugins with traditional conditional execution

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

|*Page*|*initialize*|*view*|*Total*|
| <nop>Main.PerformanceBlankPage |2.39|2.38|4.78|
| <nop>Main.WebHome |2.43|3.47|5.91|
| <nop>Main.PerformanceTestPage |2.36|2.75|5.12|
| <nop>TWiki.GoodStyle |2.36|2.87|5.24|
| <nop>TWiki.TextFormattingRules |2.52|7.85|10.38|
| <nop>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 is commonly used.

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

---+++(Control) Base Installation with DefaultPlugin and TablePlugin

|*Page*|*initialize*|*view*|*Total*|
| <nop>Main.PerformanceBlankPage |0.72|1.98|2.70|
| <nop>Main.WebHome |0.75|2.91|3.66|
| <nop>Main.PerformanceTestPage |0.75|2.21|2.96|
| <nop>TWiki.GoodStyle |0.76|2.34|3.10|
| <nop>TWiki.TextFormattingRules |0.84|6.84|7.68|
| <nop>TWiki.DefaultPlugin |0.76|2.60|3.36|
| <nop>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).

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 <nop>TWikiPreferences. The problem is in this code:

<verbatim>
	  push  @activePlugins, $plugin if not grep $plugin,@activePlugins;
</verbatim>

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

Anyway, these are the numbers:

|*Page*|*initialize*|*view*|*Total*|
| <nop>Main.PerformanceBlankPage |0.70|2.07|2.77|
| <nop>Main.WebHome |0.78|2.88|3.66|
| <nop>Main.PerformanceTestPage |0.76|2.26|3.02|
| <nop>TWiki.GoodStyle |0.78|2.35|3.13|
| <nop>TWiki.TextFormattingRules |0.84|6.81|7.65|
| <nop>TWiki.DefaultPlugin |0.75|2.59|3.34|
| <nop>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*|
| <nop>Main.PerformanceBlankPage |0.75|2.04|2.79|
| <nop>Main.WebHome |0.74|2.90|3.64|
| <nop>Main.PerformanceTestPage |0.78|2.22|3.00|
| <nop>TWiki.GoodStyle |0.74|2.39|3.13|
| <nop>TWiki.TextFormattingRules |0.86|6.78|7.63|
| <nop>TWiki.DefaultPlugin |0.75|2.59|3.34|
| <nop>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*|
| <nop>Main.PerformanceBlankPage |0.76|1.98|2.74|
| <nop>Main.WebHome |0.74|2.91|3.65|
| <nop>Main.PerformanceTestPage |0.77|2.23|3.00|
| <nop>TWiki.GoodStyle |0.76|2.35|3.11|
| <nop>TWiki.TextFormattingRules |0.87|6.80|7.67|
| <nop>TWiki.DefaultPlugin |0.74|2.59|3.33|
| <nop>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*|
| <nop>Main.PerformanceBlankPage |0.74|3.43|4.17|
| <nop>Main.WebHome |0.78|5.34|6.12|
| <nop>Main.PerformanceTestPage |0.75|3.73|4.48|
| <nop>TWiki.GoodStyle |0.76|3.88|4.65|
| <nop>TWiki.TextFormattingRules |0.84|8.30|9.14|
| <nop>TWiki.DefaultPlugin |0.74|4.08|4.82|
| <nop>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*|
| <nop>Main.PerformanceBlankPage |0.75|2.30|3.05|
| <nop>Main.WebHome |0.72|3.39|4.11|
| <nop>Main.PerformanceTestPage |0.79|2.57|3.36|
| <nop>TWiki.GoodStyle |0.78|2.69|3.47|
| <nop>TWiki.TextFormattingRules |0.87|7.24|8.11|
| <nop>TWiki.DefaultPlugin |0.78|2.84|3.62|
| <nop>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*|
| <nop>Main.PerformanceBlankPage |0.76|2.05|2.81|
| <nop>Main.WebHome |0.74|2.97|3.71|
| <nop>Main.PerformanceTestPage |0.73|2.31|3.04|
| <nop>TWiki.GoodStyle |0.77|2.41|3.18|
| <nop>TWiki.TextFormattingRules |0.89|6.91|7.80|
| <nop>TWiki.DefaultPlugin |0.78|2.58|3.36|
| <nop>TWiki.TablePlugin |0.85|5.63|6.48|

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

|*Page*|*initialize*|*view*|*Total*|
| <nop>Main.PerformanceBlankPage |0.76|2.00|2.76|
| <nop>Main.WebHome |0.75|2.93|3.68|
| <nop>Main.PerformanceTestPage |0.76|2.25|3.01|
| <nop>TWiki.GoodStyle |0.74|2.36|3.10|
| <nop>TWiki.TextFormattingRules |0.85|6.79|7.64|
| <nop>TWiki.DefaultPlugin |0.76|2.55|3.31|
| <nop>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*|
| <nop>Main.PerformanceBlankPage |0.78|2.02|2.80|
| <nop>Main.WebHome |0.76|2.89|3.65|
| <nop>Main.PerformanceTestPage |0.73|2.29|3.02|
| <nop>TWiki.GoodStyle |0.76|2.35|3.11|
| <nop>TWiki.TextFormattingRules |0.86|6.82|7.68|
| <nop>TWiki.DefaultPlugin |0.77|2.51|3.28|
| <nop>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*|
| <nop>Main.PerformanceBlankPage |0.71|2.03|2.74|
| <nop>Main.WebHome |0.73|3.02|3.75|
| <nop>Main.PerformanceTestPage |0.77|2.23|3.00|
| <nop>TWiki.GoodStyle |0.78|2.40|3.18|
| <nop>TWiki.TextFormattingRules |0.84|6.93|7.77|
| <nop>TWiki.DefaultPlugin |0.77|2.63|3.40|
| <nop>TWiki.TablePlugin |0.84|5.60|6.44|

---+++Access the other preference, OO version

|*Page*|*initialize*|*view*|*Total*|
| <nop>Main.PerformanceBlankPage |0.74|2.23|2.97|
| <nop>Main.WebHome |0.74|3.27|4.01|
| <nop>Main.PerformanceTestPage |0.77|2.47|3.24|
| <nop>TWiki.GoodStyle |0.76|2.56|3.33|
| <nop>TWiki.TextFormattingRules |0.87|6.97|7.84|
| <nop>TWiki.DefaultPlugin |0.73|2.80|3.53|
| <nop>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*|
| <nop>Main.PerformanceBlankPage |0.71|2.38|3.09|
| <nop>Main.WebHome |0.72|3.51|4.24|
| <nop>Main.PerformanceTestPage |0.75|2.60|3.35|
| <nop>TWiki.GoodStyle |0.74|2.72|3.46|
| <nop>TWiki.TextFormattingRules |0.85|7.20|8.05|
| <nop>TWiki.DefaultPlugin |0.77|2.89|3.66|
| <nop>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*|
| <nop>Main.PerformanceBlankPage |0.73|1.97|2.70|
| <nop>Main.WebHome |0.75|2.91|3.66|
| <nop>Main.PerformanceTestPage |0.75|2.20|2.95|
| <nop>TWiki.GoodStyle |0.74|2.35|3.09|
| <nop>TWiki.TextFormattingRules |0.85|6.85|7.70|
| <nop>TWiki.DefaultPlugin |0.76|2.57|3.33|
| <nop>TWiki.TablePlugin |0.82|5.53|6.35|

---+++ OO Installation

|*Page*|*initialize*|*view*|*Total*|
| <nop>Main.PerformanceBlankPage |0.75|2.05|2.80|
| <nop>Main.WebHome |0.77|2.90|3.67|
| <nop>Main.PerformanceTestPage |0.75|2.26|3.01|
| <nop>TWiki.GoodStyle |0.74|2.38|3.12|
| <nop>TWiki.TextFormattingRules |0.86|6.79|7.65|
| <nop>TWiki.DefaultPlugin |0.77|2.57|3.34|
| <nop>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*|
| <nop>Main.PerformanceBlankPage |0.75|1.97|2.72|
| <nop>Main.WebHome |0.76|3.06|3.82|
| <nop>Main.PerformanceTestPage |0.72|2.22|2.94|
| <nop>TWiki.GoodStyle |0.71|2.39|3.10|
| <nop>TWiki.TextFormattingRules |0.84|6.94|7.78|
| <nop>TWiki.DefaultPlugin |0.79|2.66|3.46|
| <nop>TWiki.TablePlugin |0.86|5.62|6.48|

---+++ OO Installation

|*Page*|*initialize*|*view*|*Total*|
| <nop>Main.PerformanceBlankPage |0.76|2.04|2.80|
| <nop>Main.WebHome |0.75|2.87|3.62|
| <nop>Main.PerformanceTestPage |0.75|2.27|3.02|
| <nop>TWiki.GoodStyle |0.76|2.33|3.09|
| <nop>TWiki.TextFormattingRules |0.85|6.79|7.64|
| <nop>TWiki.DefaultPlugin |0.74|2.55|3.29|
| <nop>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*|
| <nop>Main.PerformanceBlankPage |0.79|1.97|2.76|
| <nop>Main.WebHome |0.79|2.87|3.66|
| <nop>Main.PerformanceTestPage |0.74|2.24|2.98|
| <nop>TWiki.GoodStyle |0.75|2.36|3.11|
| <nop>TWiki.TextFormattingRules |0.90|6.71|7.61|
| <nop>TWiki.DefaultPlugin |0.77|2.51|3.28|
| <nop>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*|
| <nop>Main.PerformanceBlankPage |0.73|1.98|2.71|
| <nop>Main.WebHome |0.75|2.91|3.67|
| <nop>Main.PerformanceTestPage |0.75|2.22|2.97|
| <nop>TWiki.GoodStyle |0.77|2.37|3.14|
| <nop>TWiki.TextFormattingRules |0.82|6.90|7.72|
| <nop>TWiki.DefaultPlugin |0.75|2.59|3.34|
| <nop>TWiki.TablePlugin |0.78|5.57|6.35|

---+++ OO Installation

|*Page*|*initialize*|*view*|*Total*|
| <nop>Main.PerformanceBlankPage |0.75|2.01|2.76|
| <nop>Main.WebHome |0.76|2.92|3.67|
| <nop>Main.PerformanceTestPage |0.77|2.25|3.02|
| <nop>TWiki.GoodStyle |0.74|2.37|3.11|
| <nop>TWiki.TextFormattingRules |0.90|6.74|7.64|
| <nop>TWiki.DefaultPlugin |0.78|2.53|3.31|
| <nop>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.

