Bug 29672 - Increase performance of Koha::Plugins->call
Summary: Increase performance of Koha::Plugins->call
Status: CLOSED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: Architecture, internals, and plumbing (show other bugs)
Version: master
Hardware: All All
: P5 - low enhancement (vote)
Assignee: Julian Maurice
QA Contact: Kyle M Hall
URL:
Keywords:
Depends on:
Blocks: 7923
  Show dependency treegraph
 
Reported: 2021-12-09 14:34 UTC by Julian Maurice
Modified: 2023-12-28 20:43 UTC (History)
8 users (show)

See Also:
Change sponsored?: ---
Patch complexity: Small patch
Documentation contact:
Documentation submission:
Text to go in the release notes:
Version(s) released in:
22.11.00


Attachments
Bug 29672: Increase performance of Koha::Plugins->call (3.83 KB, patch)
2021-12-09 14:36 UTC, Julian Maurice
Details | Diff | Splinter Review
Bug 29672: [DO NOT PUSH] Test script (1.10 KB, patch)
2021-12-09 14:37 UTC, Julian Maurice
Details | Diff | Splinter Review
Bug 29672: Increase performance of Koha::Plugins->call (4.42 KB, patch)
2022-06-03 07:43 UTC, Julian Maurice
Details | Diff | Splinter Review
Bug 29672: [DO NOT PUSH] Test script (1.10 KB, patch)
2022-06-03 07:43 UTC, Julian Maurice
Details | Diff | Splinter Review
Bug 29672: Clear cache of enabled plugins when a plugin's state change (2.45 KB, patch)
2022-06-06 07:19 UTC, Julian Maurice
Details | Diff | Splinter Review
Bug 29672: [DO NOT PUSH] Test script (1.15 KB, patch)
2022-11-01 00:36 UTC, David Nind
Details | Diff | Splinter Review
Bug 29672: Increase performance of Koha::Plugins->call (4.47 KB, patch)
2022-11-01 00:36 UTC, David Nind
Details | Diff | Splinter Review
Bug 29672: Clear cache of enabled plugins when a plugin's state change (2.50 KB, patch)
2022-11-01 00:36 UTC, David Nind
Details | Diff | Splinter Review
Bug 29672: Fix test t/db_dependent/Koha/Plugins/Plugins.t (1.16 KB, patch)
2022-11-02 08:48 UTC, Julian Maurice
Details | Diff | Splinter Review
Bug 29672: [DO NOT PUSH] Test script (1.21 KB, patch)
2022-11-02 11:17 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 29672: Increase performance of Koha::Plugins->call (4.53 KB, patch)
2022-11-02 11:17 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 29672: Clear cache of enabled plugins when a plugin's state change (2.55 KB, patch)
2022-11-02 11:17 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 29672: Fix test t/db_dependent/Koha/Plugins/Plugins.t (1.22 KB, patch)
2022-11-02 11:17 UTC, Kyle M Hall
Details | Diff | Splinter Review
Bug 29672: (QA followup) Add POD (708 bytes, patch)
2022-11-02 11:17 UTC, Kyle M Hall
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Julian Maurice 2021-12-09 14:34:30 UTC
Every call to Koha::Plugins->call do a lot of database queries:
1) One in GetPlugins searches for available plugin_class in plugin_methods table
2) One in Koha::Plugins::Base::is_enabled for each plugin returned by (1)
3) One or two in Koha::Plugins::Base::new for each plugin returned by (1) to check the install status and the installed version

All of these requests only need to be made once per HTTP request at most. One could argue that it's needed only at Koha startup but that besides the point of this bug report.
Comment 1 Julian Maurice 2021-12-09 14:36:56 UTC
Created attachment 128376 [details] [review]
Bug 29672: Increase performance of Koha::Plugins->call

Make use of Koha::Cache::Memory::Lite to avoid hitting the database and
creating plugins object for every call to Koha::Plugins->call

Test plan:
1. Make sure plugins still work by executing
   `prove t/db_dependent/Koha/Plugins/Plugins.t`
2. Run the test script provided in the following patch to see how it
   affects performances
Comment 2 Julian Maurice 2021-12-09 14:37:01 UTC
Created attachment 128377 [details] [review]
Bug 29672: [DO NOT PUSH] Test script

Run test-plugins-call.pl without arguments with and without the patches,
with some plugins enabled. Make sure to run
misc/devel/install_plugins.pl before
Comment 3 Julian Maurice 2021-12-09 14:39:43 UTC
Times I get on master:

1 call(s): Elapsed 0.670997 seconds
10 call(s): Elapsed 0.049056 seconds
100 call(s): Elapsed 0.468099 seconds
1000 call(s): Elapsed 4.762553 seconds

Times I get with the patch:

1 call(s): Elapsed 0.634319 seconds
10 call(s): Elapsed 0.000154 seconds
100 call(s): Elapsed 0.001282 seconds
1000 call(s): Elapsed 0.011682 seconds

As you can see the first call takes the same time with or without the patch, but subsequent calls are much more faster with the patch
Comment 4 Fridolin Somers 2021-12-10 06:35:33 UTC
I see it returns undef when plugins are disabled.
It should return empty array non ?

In order to allow :

my @plugin_responses = Koha::Plugins->call(
    'opac_results_xslt_variables',
    {
        lang       => $lang,
        patron_id  => $borrowernumber
    }
);
for my $plugin_variables ( @plugin_responses ) {
    $variables = { %$variables, %$plugin_variables };
}
Comment 5 Fridolin Somers 2021-12-10 06:40:41 UTC
(In reply to Fridolin Somers from comment #4)
> I see it returns undef when plugins are disabled.
> It should return empty array non ?
> 
> In order to allow :
> 
> my @plugin_responses = Koha::Plugins->call(
>     'opac_results_xslt_variables',
>     {
>         lang       => $lang,
>         patron_id  => $borrowernumber
>     }
> );
> for my $plugin_variables ( @plugin_responses ) {
>     $variables = { %$variables, %$plugin_variables };
> }

Oh i see it is covered by a unit test :
    t::lib::Mocks::mock_config('enable_plugins', 0);
    @responses = Koha::Plugins->call('check_password', { password => '1234' });
    is_deeply(\@responses, [], 'call() should return an empty array if plugins are disabled');

Should be OK :)
Comment 6 Fridolin Somers 2021-12-10 07:00:02 UTC
Instead of creating get_enabled_plugins(),
Why not adding a param "only_enabled" in GetPlugins() ?
Comment 7 Julian Maurice 2021-12-10 07:11:29 UTC
(In reply to Fridolin Somers from comment #6)
> Instead of creating get_enabled_plugins(),
> Why not adding a param "only_enabled" in GetPlugins() ?

GetPlugins already returns only enabled plugins by default (without the 'all' parameter), but it also have other parameters that make it hard for its result to be put in cache.
Comment 8 Fridolin Somers 2021-12-13 21:32:02 UTC
Ah OK thanks.

get_enabled_plugins () is a private method ? maybe rename _get_enabled_plugins()

Best regards,
Comment 9 Jonathan Druart 2021-12-15 09:28:57 UTC
Julian, I am not sure, you are bypassing Koha::Plugin::Base->retrieve_data that is used in other places. As we are actually looking at caching the result, why not keep the usual way to retrieve the enabled plugins then cache them?
Comment 10 Jonathan Druart 2021-12-15 09:29:22 UTC
(In reply to Fridolin Somers from comment #8)
> Ah OK thanks.
> 
> get_enabled_plugins () is a private method ? maybe rename
> _get_enabled_plugins()
> 
> Best regards,

It's a class method, like all other methods from this module.
Comment 11 Fridolin Somers 2021-12-15 22:50:34 UTC
(In reply to Jonathan Druart from comment #10)
> (In reply to Fridolin Somers from comment #8)
> > Ah OK thanks.
> > 
> > get_enabled_plugins () is a private method ? maybe rename
> > _get_enabled_plugins()
> > 
> > Best regards,
> 
> It's a class method, like all other methods from this module.

Ah OK thanks.

Now i see there is :
 my ($class) = @_;
Comment 12 Julian Maurice 2021-12-16 07:24:11 UTC
(In reply to Jonathan Druart from comment #9)
> Julian, I am not sure, you are bypassing Koha::Plugin::Base->retrieve_data
> that is used in other places. As we are actually looking at caching the
> result, why not keep the usual way to retrieve the enabled plugins then
> cache them?

I guess you're talking about the is_enabled method (which calls retrieve_data) ?
I think we should not ask the plugin itself if it's enabled because a plugin can override this method.
It also produces less SQL queries that way (one query to retrieve all enabled plugins, instead of one query per module)
Comment 13 Jonathan Druart 2022-06-02 08:01:56 UTC
Kyle, Tomas, could you have a look at this improvement?
Comment 14 Kyle M Hall 2022-06-02 11:04:45 UTC
> I guess you're talking about the is_enabled method (which calls
> retrieve_data) ?
> I think we should not ask the plugin itself if it's enabled because a plugin
> can override this method.
> It also produces less SQL queries that way (one query to retrieve all
> enabled plugins, instead of one query per module)

I think this is a reasonable stance to take. We control the internals so we don't need to make is_enabled a chokepoint. A single query selecting all plugins where plugins data __ENABLED__ is 1 seems like a good idea to me.
Comment 15 Tomás Cohen Arazi 2022-06-02 12:10:47 UTC
I like the approach of using the Lite cache and avoid subsequent queries.
Comment 16 David Cook 2022-06-02 23:53:38 UTC
I like the concept.

A few questions:

1) Why does get_enabled_plugins return the array rather than an array reference? (I suppose it might not matter much since the array will just be a list of references itself, but it just seems less efficient.)

2) Each Koha::Plugins->call() loops through the plugin list checking the methods available. If there is a large plugin list, this will scale linearly and be progressively slower. 

Since we're already looping through the plugins in get_enabled_plugins, it could be a good idea to do that method check at the same time and build a hash map of methods to plugins. (The downside is that you'd have to pre-check all methods rather than lazily check just the methods you're demanding at method call time, but that expense would be 1 time rather than N times.)

I think that would maek sense since what we're really trying to do here is "get_enabled_plugins_with_method", right?
Comment 17 David Cook 2022-06-03 00:03:13 UTC
(In reply to David Cook from comment #16)
> I think that would maek sense since what we're really trying to do here is
> "get_enabled_plugins_with_method", right?

Actually, why not create "get_enabled_plugins_with_method"? 

We store the methods in a table too, so you could fetch all enabled plugins for method X, and then cache those plugins.

That way, you're just caching a list of plugins for methods that are used. That means every call of "$_->can($method)" *should* be true, so there should be no wasted loops.

That said, you could wind up with multiple plugin objects in different cached hash maps. I suppose you could work around that by having 2 cached hash maps. 

But I suppose that's growing in complexity. 

Anyway just my two cents.
Comment 18 Julian Maurice 2022-06-03 06:41:49 UTC
(In reply to David Cook from comment #16)
> 1) Why does get_enabled_plugins return the array rather than an array
> reference? (I suppose it might not matter much since the array will just be
> a list of references itself, but it just seems less efficient.)
Is it really less efficient ? We have to de-reference the list at some point to iterate over it anyway. I will be happy to change that if you can show that it impacts performance.

> 2) Each Koha::Plugins->call() loops through the plugin list checking the
> methods available. If there is a large plugin list, this will scale linearly
> and be progressively slower. 
It only calls 'can' in the loop. How many calls to 'can' does it take to slow down Koha ? I tested this and on my laptop 5000 'can' calls on a DateTime object takes 1ms. 
Which sane person would install 5000 Koha plugins ? :)
And if they do, that 1ms lost here is not what I would worry about.

> Since we're already looping through the plugins in get_enabled_plugins, it
> could be a good idea to do that method check at the same time and build a
> hash map of methods to plugins. (The downside is that you'd have to
> pre-check all methods rather than lazily check just the methods you're
> demanding at method call time, but that expense would be 1 time rather than
> N times.)
And most of the time 95% of the methods pre-checked won't be used until the next pre-check. That is wasted time IMO. I'm not sure if this would be an improvement.
Comment 19 David Cook 2022-06-03 07:13:20 UTC
(In reply to Julian Maurice from comment #18)
> Is it really less efficient ? We have to de-reference the list at some point
> to iterate over it anyway. I will be happy to change that if you can show
> that it impacts performance.
 
It would be less efficient as you're creating a new data structure in memory and copying the list contents over to it. But the difference is probably negligible, so I wouldn't worry about it. It just seemed like an odd choice to me. 

> It only calls 'can' in the loop. How many calls to 'can' does it take to
> slow down Koha ? I tested this and on my laptop 5000 'can' calls on a
> DateTime object takes 1ms. 
> Which sane person would install 5000 Koha plugins ? :)
> And if they do, that 1ms lost here is not what I would worry about.

I thought that I wrote the same thing earlier but apparently I didn't. Yeah, "can" would be a very cheap call. No I/O to do. Just a wee bit of CPU time. 
 
> And most of the time 95% of the methods pre-checked won't be used until the
> next pre-check. That is wasted time IMO. I'm not sure if this would be an
> improvement.

In my follow-up comment, I was suggesting that you could actually just fetch the plugins that support the method you need and cache those plugins without fetching, instantiating, and caching all the plugins. 

But then you could argue there's not that many plugins, so you could just fetch them all. No point optimizing until you need to. 

--

In any case, +1 to caching
Comment 20 Jonathan Druart 2022-06-03 07:34:57 UTC
CONFLICT (content): Merge conflict in Koha/Plugins.pm                                                               
Patch failed at 0001 Bug 29672: Increase performance of Koha::Plugins->call
Comment 21 Julian Maurice 2022-06-03 07:43:05 UTC
Created attachment 135660 [details] [review]
Bug 29672: Increase performance of Koha::Plugins->call

Make use of Koha::Cache::Memory::Lite to avoid hitting the database and
creating plugins object for every call to Koha::Plugins->call

Test plan:
1. Make sure plugins still work by executing
   `prove t/db_dependent/Koha/Plugins/Plugins.t`
2. Run the test script provided in the following patch to see how it
   affects performances
Comment 22 Julian Maurice 2022-06-03 07:43:10 UTC
Created attachment 135661 [details] [review]
Bug 29672: [DO NOT PUSH] Test script

Run test-plugins-call.pl without arguments with and without the patches,
with some plugins enabled. Make sure to run
misc/devel/install_plugins.pl before
Comment 23 Jonathan Druart 2022-06-03 12:25:23 UTC
I think we should invalidate/clean the cache when a new plugin is installed/enabled/disabled. You will certainly need the second patch from bug 29623.
Comment 24 Julian Maurice 2022-06-03 12:32:35 UTC
(In reply to Jonathan Druart from comment #23)
> I think we should invalidate/clean the cache when a new plugin is
> installed/enabled/disabled.
I agree

> You will certainly need the second patch from bug 29623.
I don't think so. There is only one key to flush here, so we don't need the list of all keys.
Comment 25 Julian Maurice 2022-06-06 07:19:21 UTC
Created attachment 135704 [details] [review]
Bug 29672: Clear cache of enabled plugins when a plugin's state change
Comment 26 David Nind 2022-11-01 00:36:33 UTC
Created attachment 142844 [details] [review]
Bug 29672: [DO NOT PUSH] Test script

Run test-plugins-call.pl without arguments with and without the patches,
with some plugins enabled. Make sure to run
misc/devel/install_plugins.pl before

Signed-off-by: David Nind <david@davidnind.com>
Comment 27 David Nind 2022-11-01 00:36:38 UTC
Created attachment 142845 [details] [review]
Bug 29672: Increase performance of Koha::Plugins->call

Make use of Koha::Cache::Memory::Lite to avoid hitting the database and
creating plugins object for every call to Koha::Plugins->call

Test plan:
1. Make sure plugins still work by executing
   `prove t/db_dependent/Koha/Plugins/Plugins.t`
2. Run the test script provided in the following patch to see how it
   affects performances

Signed-off-by: David Nind <david@davidnind.com>
Comment 28 David Nind 2022-11-01 00:36:42 UTC
Created attachment 142846 [details] [review]
Bug 29672: Clear cache of enabled plugins when a plugin's state change

Signed-off-by: David Nind <david@davidnind.com>
Comment 29 David Nind 2022-11-01 00:53:17 UTC
Apologies, I signed off and then reealised that I hadn't run the tests after applying the patches!

Tests now fail after the patches are applied. Weirdly, running the tests seemed to uninstall the plugins. I reinstalled the plugins again, flush_memcached + restart_all, and ran the tests again - they failed [4].

Testing notes (using koha-testing-docker):
1. Ran prove t/db_dependent/Koha/Plugins/Plugins.t - tests passed
2. Installed 2 plugins and enabled
3. Ran misc/devel/install_plugins.pl [1]
4. Applied test script patch and ran [2]
5. Applied other patches and flush_memcached + restart_all
6. Re-ran test script [3]
7. Ran prove t/db_dependent/Koha/Plugins/Plugins.t - tests failed

[1] Output from running misc/devel/install_plugins.pl:

misc/devel/install_plugins.pl
Installed Example Kitchen-Sink Plugin version 2.3.0
Installed BiblbioCommons connector plugin for Koha version 0.5.3
All plugins successfully re-initialised

[2] Output of the test script BEFORE the patches were applied:

./test-plugins-call.pl
1 call(s): Elapsed 0.686131 seconds
10 call(s): Elapsed 0.093689 seconds
100 call(s): Elapsed 0.572402 seconds
1000 call(s): Elapsed 5.629604 seconds

[3] Output of the test script AFTER the patches were applied:

./test-plugins-call.pl
1 call(s): Elapsed 0.683855 seconds
10 call(s): Elapsed 0.000213 seconds
100 call(s): Elapsed 0.001843 seconds
1000 call(s): Elapsed 0.017745 seconds

[4] Tests fail after patches are applied:

prove t/db_dependent/Koha/Plugins/Plugins.t
t/db_dependent/Koha/Plugins/Plugins.t .. 6/61 
    #   Failed test at t/db_dependent/Koha/Plugins/Plugins.t line 112.
    # found warning: Failed to load Koha::Plugin::Com::ByWaterSolutions::KitchenSink: Could not find or check module 'Koha::Plugin::Com::ByWaterSolutions::KitchenSink' at /kohadevbox/koha/Koha/Plugins.pm line 116.
    # found warning: Failed to load Koha::Plugin::Com::Theke::BiblioCommons: Could not find or check module 'Koha::Plugin::Com::Theke::BiblioCommons' at /kohadevbox/koha/Koha/Plugins.pm line 116.
    # found warning: Plugin error (Test Plugin): Exception 'Koha::Exception' thrown 'item_barcode_transform called with parameter: 1'
    # found warning: Plugin error (Test Plugin for item_barcode_transform): Exception 'Koha::Exception' thrown 'item_barcode_transform called with parameter: 2'
    # expected to find warning: Plugin error (Test Plugin): Exception 'Koha::Exception' thrown 'item_barcode_transform called with parameter: 1'
    # expected to find warning: Plugin error (Test Plugin for item_barcode_transform): Exception 'Koha::Exception' thrown 'item_barcode_transform called with parameter: 2'
    # Looks like you failed 1 test of 6.

#   Failed test 'more call() tests'
#   at t/db_dependent/Koha/Plugins/Plugins.t line 129.
t/db_dependent/Koha/Plugins/Plugins.t .. 48/61 # Looks like you failed 1 test of 61.
t/db_dependent/Koha/Plugins/Plugins.t .. Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/61 subtests 

Test Summary Report
-------------------
t/db_dependent/Koha/Plugins/Plugins.t (Wstat: 256 Tests: 61 Failed: 1)
  Failed test:  7
  Non-zero exit status: 1
Files=1, Tests=61,  3 wallclock secs ( 0.03 usr  0.01 sys +  2.63 cusr  0.24 csys =  2.91 CPU)
Result: FAIL
Comment 30 Julian Maurice 2022-11-02 08:48:36 UTC
Created attachment 142916 [details] [review]
Bug 29672: Fix test t/db_dependent/Koha/Plugins/Plugins.t

Table plugin_data was not always cleared
Comment 31 Kyle M Hall 2022-11-02 11:17:00 UTC
Created attachment 142919 [details] [review]
Bug 29672: [DO NOT PUSH] Test script

Run test-plugins-call.pl without arguments with and without the patches,
with some plugins enabled. Make sure to run
misc/devel/install_plugins.pl before

Signed-off-by: David Nind <david@davidnind.com>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 32 Kyle M Hall 2022-11-02 11:17:30 UTC
Created attachment 142920 [details] [review]
Bug 29672: Increase performance of Koha::Plugins->call

Make use of Koha::Cache::Memory::Lite to avoid hitting the database and
creating plugins object for every call to Koha::Plugins->call

Test plan:
1. Make sure plugins still work by executing
   `prove t/db_dependent/Koha/Plugins/Plugins.t`
2. Run the test script provided in the following patch to see how it
   affects performances

Signed-off-by: David Nind <david@davidnind.com>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 33 Kyle M Hall 2022-11-02 11:17:35 UTC
Created attachment 142921 [details] [review]
Bug 29672: Clear cache of enabled plugins when a plugin's state change

Signed-off-by: David Nind <david@davidnind.com>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 34 Kyle M Hall 2022-11-02 11:17:40 UTC
Created attachment 142922 [details] [review]
Bug 29672: Fix test t/db_dependent/Koha/Plugins/Plugins.t

Table plugin_data was not always cleared

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 35 Kyle M Hall 2022-11-02 11:17:45 UTC
Created attachment 142923 [details] [review]
Bug 29672: (QA followup) Add POD

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 36 Tomás Cohen Arazi 2022-11-03 14:32:03 UTC
Pushed to master for 22.11.

Nice work everyone, thanks!
Comment 37 Marcel de Rooy 2022-12-12 12:01:14 UTC
(In reply to Julian Maurice from comment #7)
> (In reply to Fridolin Somers from comment #6)
> > Instead of creating get_enabled_plugins(),
> > Why not adding a param "only_enabled" in GetPlugins() ?
> 
> GetPlugins already returns only enabled plugins by default (without the
> 'all' parameter), but it also have other parameters that make it hard for
> its result to be put in cache.

The all parameter is not used often and could perhaps live on its own. The results of GetPlugins might be filtered by method or metadata, but that could be done too on the cached results, just limiting them further?

We now have two similar routines. One has been optimized, the other one not. Note that GetPlugins is still called in the codebase, probably on the first places when we did not yet have ->call. Feels a bit like unfinished work?