Bug 32092

Summary: Improve circulation rules cache utilization
Product: Koha Reporter: David Gustafsson <glasklas>
Component: Architecture, internals, and plumbingAssignee: David Gustafsson <glasklas>
Status: Needs Signoff --- QA Contact: Kyle M Hall <kyle>
Severity: enhancement    
Priority: P5 - low CC: emily.lamancusa, fridolin.somers, jonathan.druart, kyle, matthias.le-gac
Version: Main   
Hardware: All   
OS: All   
Change sponsored?: --- Patch complexity: ---
Documentation contact: Documentation submission:
Text to go in the release notes:
Version(s) released in:
Bug Depends on: 29623    
Bug Blocks:    
Attachments: Bug 32092: Improve circulation rules cache utilization
Bug 32092: Improve circulation rules cache utilization
Bug 32092: Fix tests
Bug 32092: Improve circulation rules cache utilization
Bug 32092: Fix tests
Bug 32092: Improve circulation rules cache utilization
Bug 32092: Fix tests
Before
After
Bug 32092: Fix uninitialized value in addition
Bug 32092: Improve circulation rules cache utilization
Bug 32092: Fix tests
Bug 32092: Fix uninitialized value in addition
Bug 32092: Improve circulation rules cache utilization
Bug 32092: Fix tests
Bug 32092: Fix uninitialized value in addition
Bug 32092: Improve circulation rules cache utilization
Bug 32092: Fix tests
Bug 32092: Fix uninitialized value in addition
Bug 32092: Fix regression in TooMany and some missed cases
Bug 32092: Fix regression in TooMany and some missed cases

Description David Gustafsson 2022-11-03 14:23:01 UTC
Currently the cache is bypassed when fetching of circulation rules in a lot of places, calling get_effective_rule instead of get_effective_rule_value which makes use of in-memory cached. Additionally the case where the rule value is an empty string or undefined or no rule is found are not currently cached which results in the database is being queried repeatedly for cases where no results are found (which usually are the majority of calls). For example on the page where items are listed when placing a hold the current hit ratio for the cache in get_effective_rule_value is about 6%, with this patch we instead get a hit ratio of 99.8%, resulting in a whooping 340x less time spent performing the database lookup in get_effective_rule_value. With 150 items (we have serials with up to 1400 items), about 50% of the execution time is spent looking up rules which is practically reduced to zero when also caching empty results (and replacing the uncached direct calls to get_effective_rule with get_effective_rule_value).
Comment 1 David Gustafsson 2022-11-03 14:40:56 UTC
Created attachment 143120 [details] [review]
Bug 32092: Improve circulation rules cache utilization

To test:
1) Go to the page for placing a hold for a biblio with a large
   number of items
2) Depending on the number of items this page can be very slow
   to load
3) Ensure the following tests pass:
   t/db_dependent/Circulation.t
   t/db_dependent/Reserves.t
   t/db_dependent/Biblio.t
   t/db_dependent/Koha/Charges/Fees.t
   t/db_dependent/Koha/Charges/Fees.t
   t/db_dependent/Items.t
   t/db_dependent/Koha/Patron.t
   t/db_dependent/api/v1/checkouts.t
   t/db_dependent/Koha/Template/Plugin/CirculationRules.t
   t/db_dependent/Template/Plugin/CirculationRules.t
3) Apply the patch
4) The page loading time should now be significantly faster
5) Ensure all the tests in 3) still pass

Sponsored-by: Gothenburg University Library
Comment 2 Fridolin Somers 2022-12-05 08:12:10 UTC
If I understand right :
Depends on Bug 29623 that created get_effective_rule_value()
Comment 3 David Gustafsson 2023-02-20 12:59:48 UTC
Created attachment 146956 [details] [review]
Bug 32092: Improve circulation rules cache utilization

To test:
1) Go to the page for placing a hold for a biblio with a large
   number of items
2) Depending on the number of items this page can be very slow
   to load
3) Ensure the following tests pass:
   t/db_dependent/Circulation.t
   t/db_dependent/Reserves.t
   t/db_dependent/Biblio.t
   t/db_dependent/Koha/Charges/Fees.t
   t/db_dependent/Koha/Charges/Fees.t
   t/db_dependent/Items.t
   t/db_dependent/Koha/Patron.t
   t/db_dependent/api/v1/checkouts.t
   t/db_dependent/Koha/Template/Plugin/CirculationRules.t
   t/db_dependent/Template/Plugin/CirculationRules.t
3) Apply the patch
4) The page loading time should now be significantly faster
5) Ensure all the tests in 3) still pass

Sponsored-by: Gothenburg University Library
Comment 4 David Gustafsson 2023-02-20 13:02:38 UTC
(In reply to Fridolin Somers from comment #2)
> If I understand right :
> Depends on Bug 29623 that created get_effective_rule_value()

Yes, but that on is in the current master?

Where some conflicts so have rebased against latest master.
Comment 5 Fridolin Somers 2023-02-22 08:20:30 UTC
Yes it is in current master and 22.11.x.
The dependency will be useful for RMaint of < 22.11.x
Comment 6 David Gustafsson 2023-02-22 13:51:31 UTC
Created attachment 147149 [details] [review]
Bug 32092: Fix tests
Comment 7 David Gustafsson 2023-02-22 13:52:59 UTC
Created attachment 147150 [details] [review]
Bug 32092: Improve circulation rules cache utilization

To test:
1) Go to the page for placing a hold for a biblio with a large
   number of items
2) Depending on the number of items this page can be very slow
   to load
3) Ensure the following tests pass:
   t/db_dependent/Circulation.t
   t/db_dependent/Reserves.t
   t/db_dependent/Biblio.t
   t/db_dependent/Koha/Charges/Fees.t
   t/db_dependent/Koha/Charges/Fees.t
   t/db_dependent/Items.t
   t/db_dependent/Koha/Patron.t
   t/db_dependent/api/v1/checkouts.t
   t/db_dependent/Koha/Template/Plugin/CirculationRules.t
   t/db_dependent/Template/Plugin/CirculationRules.t
   t/db_dependent/Koha/CirculationRules.t
3) Apply the patch
4) The page loading time should now be significantly faster
5) Ensure all the tests in 3) still pass

Sponsored-by: Gothenburg University Library
Comment 8 David Gustafsson 2023-02-22 13:53:01 UTC
Created attachment 147151 [details] [review]
Bug 32092: Fix tests
Comment 9 Emily Lamancusa 2023-04-17 21:08:20 UTC
Created attachment 149782 [details] [review]
Bug 32092: Improve circulation rules cache utilization

To test:
1) Go to the page for placing a hold for a biblio with a large
   number of items
2) Depending on the number of items this page can be very slow
   to load
3) Ensure the following tests pass:
   t/db_dependent/Circulation.t
   t/db_dependent/Reserves.t
   t/db_dependent/Biblio.t
   t/db_dependent/Koha/Charges/Fees.t
   t/db_dependent/Koha/Charges/Fees.t
   t/db_dependent/Items.t
   t/db_dependent/Koha/Patron.t
   t/db_dependent/api/v1/checkouts.t
   t/db_dependent/Koha/Template/Plugin/CirculationRules.t
   t/db_dependent/Template/Plugin/CirculationRules.t
   t/db_dependent/Koha/CirculationRules.t
3) Apply the patch
4) The page loading time should now be significantly faster
5) Ensure all the tests in 3) still pass

Sponsored-by: Gothenburg University Library
Signed-off-by: Emily Lamancusa <emily.lamancusa@montgomerycountymd.gov>
Comment 10 Emily Lamancusa 2023-04-17 21:08:22 UTC
Created attachment 149783 [details] [review]
Bug 32092: Fix tests

Signed-off-by: Emily Lamancusa <emily.lamancusa@montgomerycountymd.gov>
Comment 11 Emily Lamancusa 2023-04-17 21:32:51 UTC
Notes for QA team:
- Circulation.t failed on master before applying the patch, and produced identical output after applying the patch.

- Perl gave the warning, "Use of uninitialized value in addition (+)" warning for Patron.pm line 1091 when running the tests. It looks like + 0 was added to the output of the function to force an empty result to store as 0 rather than "", yes? The tests still passed and as far as I know this doesn't need to block a signoff, but noting it out of thoroughness in case it matters.
Comment 12 Kyle M Hall 2023-05-12 14:37:15 UTC
Can you show create a script or test or another way to demonstrate the speed improvement? I used multitime to test and it appears to be a bit slower with your patches. If your code is indeed faster, I'm wondering if the additional cache flushing is causing the issue

Master:
1: prove t/db_dependent/Circulation.t t/db_dependent/Reserves.t t/db_dependent/Biblio.t t/db_dependent/Koha/Charges/Fees.t t/db_dependent/Items.t t/db_dependent/Koha/Patron.t t/db_dependent/api/v1/checkouts.t t/db_dependent/Koha/Template/Plugin/CirculationRules.t
            Mean        Std.Dev.    Min         Median      Max
real        41.937      2.340       38.932      41.881      46.608
user        35.524      1.881       33.089      35.399      39.304
sys         4.245       0.429       3.624       4.191       4.969

Both Patches:
1: prove t/db_dependent/Circulation.t t/db_dependent/Reserves.t t/db_dependent/Biblio.t t/db_dependent/Koha/Charges/Fees.t t/db_dependent/Items.t t/db_dependent/Koha/Patron.t t/db_dependent/api/v1/checkouts.t t/db_dependent/Koha/Template/Plugin/CirculationRules.t
            Mean        Std.Dev.    Min         Median      Max
real        42.670      2.010       39.200      42.716      45.849
user        35.969      1.485       33.404      35.807      38.477
sys         4.444       0.457       3.742       4.612       5.096

Without the "Fix tests" Patch:
1: prove t/db_dependent/Circulation.t t/db_dependent/Reserves.t t/db_dependent/Biblio.t t/db_dependent/Koha/Charges/Fees.t t/db_dependent/Items.t t/db_dependent/Koha/Patron.t t/db_dependent/api/v1/checkouts.t t/db_dependent/Koha/Template/Plugin/CirculationRules.t
            Mean        Std.Dev.    Min         Median      Max
real        41.730      1.535       40.115      41.217      45.135
user        35.400      1.165       34.116      34.928      37.987
sys         4.158       0.345       3.633       4.152       4.908
Comment 13 David Gustafsson 2023-05-12 15:19:30 UTC
(In reply to Kyle M Hall from comment #12)
> Can you show create a script or test or another way to demonstrate the speed
> improvement? I used multitime to test and it appears to be a bit slower with
> your patches. If your code is indeed faster, I'm wondering if the additional
> cache flushing is causing the issue
> 
> Master:
> 1: prove t/db_dependent/Circulation.t t/db_dependent/Reserves.t
> t/db_dependent/Biblio.t t/db_dependent/Koha/Charges/Fees.t
> t/db_dependent/Items.t t/db_dependent/Koha/Patron.t
> t/db_dependent/api/v1/checkouts.t
> t/db_dependent/Koha/Template/Plugin/CirculationRules.t
>             Mean        Std.Dev.    Min         Median      Max
> real        41.937      2.340       38.932      41.881      46.608
> user        35.524      1.881       33.089      35.399      39.304
> sys         4.245       0.429       3.624       4.191       4.969
> 
> Both Patches:
> 1: prove t/db_dependent/Circulation.t t/db_dependent/Reserves.t
> t/db_dependent/Biblio.t t/db_dependent/Koha/Charges/Fees.t
> t/db_dependent/Items.t t/db_dependent/Koha/Patron.t
> t/db_dependent/api/v1/checkouts.t
> t/db_dependent/Koha/Template/Plugin/CirculationRules.t
>             Mean        Std.Dev.    Min         Median      Max
> real        42.670      2.010       39.200      42.716      45.849
> user        35.969      1.485       33.404      35.807      38.477
> sys         4.444       0.457       3.742       4.612       5.096
> 
> Without the "Fix tests" Patch:
> 1: prove t/db_dependent/Circulation.t t/db_dependent/Reserves.t
> t/db_dependent/Biblio.t t/db_dependent/Koha/Charges/Fees.t
> t/db_dependent/Items.t t/db_dependent/Koha/Patron.t
> t/db_dependent/api/v1/checkouts.t
> t/db_dependent/Koha/Template/Plugin/CirculationRules.t
>             Mean        Std.Dev.    Min         Median      Max
> real        41.730      1.535       40.115      41.217      45.135
> user        35.400      1.165       34.116      34.928      37.987
> sys         4.158       0.345       3.633       4.152       4.908

Circulation rules are rarely (if ever) fetched more than once in those tests, and for the difference to be noticeable you would have to access the rules within some kind of loop iterating over a larger number of items (for example). Don't have a lot of time on my hands right now so providing a script will probably take some time. What I could do meanwhile is to upload a flame graph before and after the patch with the test case have been using.
Comment 14 David Gustafsson 2023-05-12 16:08:22 UTC
Will attach the flame graph data on monday.
Comment 15 Emily Lamancusa 2023-05-12 16:19:03 UTC
It sounds like you're looking for something more rigorous, but I can provide a little more info on the results I got when testing for sign-off, if that's helpful:

For my testing, I used the "add multiple copies" feature to create a bib with 400 items split between 4 branches. I then timed the page loads for placing a hold a few times on master and a few times with the patch (nothing fancy, just literally used a stopwatch timer). I got page loads taking about 18-23 seconds on master, and 9-11 seconds with the patch.

As I said, not statistically rigorous, but definitely noticeable.
Comment 16 David Gustafsson 2023-05-15 13:53:55 UTC
(In reply to Emily Lamancusa from comment #15)
> It sounds like you're looking for something more rigorous, but I can provide
> a little more info on the results I got when testing for sign-off, if that's
> helpful:
> 
> For my testing, I used the "add multiple copies" feature to create a bib
> with 400 items split between 4 branches. I then timed the page loads for
> placing a hold a few times on master and a few times with the patch (nothing
> fancy, just literally used a stopwatch timer). I got page loads taking about
> 18-23 seconds on master, and 9-11 seconds with the patch.
> 
> As I said, not statistically rigorous, but definitely noticeable.

That's great :) I didn't know about that feature, very useful for testing this and similar patches. I think testing the way you did is completely sufficient, but will also attach to flame graphs so can see what parts of the code is sped up.

Basically, without the patch 44.3s is spent in Koha::CirculationRules::get_effective_rule, with the patch that time is reduced to 49.9ms (for this particular benchmark using about 1400 items).
Comment 17 David Gustafsson 2023-05-15 13:56:46 UTC
Created attachment 151195 [details]
Before
Comment 18 David Gustafsson 2023-05-15 13:57:07 UTC
Created attachment 151196 [details]
After
Comment 19 David Gustafsson 2023-05-15 14:08:24 UTC
Created attachment 151197 [details] [review]
Bug 32092: Fix uninitialized value in addition
Comment 20 David Gustafsson 2023-05-15 14:09:49 UTC
@Emily Lamancusa thanks for spotting the warning the previous code did not produce, this should now be fixed.
Comment 21 Kyle M Hall 2023-05-25 19:04:38 UTC
Created attachment 151709 [details] [review]
Bug 32092: Improve circulation rules cache utilization

To test:
1) Go to the page for placing a hold for a biblio with a large
   number of items
2) Depending on the number of items this page can be very slow
   to load
3) Ensure the following tests pass:
   t/db_dependent/Circulation.t
   t/db_dependent/Reserves.t
   t/db_dependent/Biblio.t
   t/db_dependent/Koha/Charges/Fees.t
   t/db_dependent/Koha/Charges/Fees.t
   t/db_dependent/Items.t
   t/db_dependent/Koha/Patron.t
   t/db_dependent/api/v1/checkouts.t
   t/db_dependent/Koha/Template/Plugin/CirculationRules.t
   t/db_dependent/Template/Plugin/CirculationRules.t
   t/db_dependent/Koha/CirculationRules.t
3) Apply the patch
4) The page loading time should now be significantly faster
5) Ensure all the tests in 3) still pass

Sponsored-by: Gothenburg University Library
Signed-off-by: Emily Lamancusa <emily.lamancusa@montgomerycountymd.gov>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 22 Kyle M Hall 2023-05-25 19:04:45 UTC
Created attachment 151710 [details] [review]
Bug 32092: Fix tests

Signed-off-by: Emily Lamancusa <emily.lamancusa@montgomerycountymd.gov>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 23 Kyle M Hall 2023-05-25 19:04:48 UTC
Created attachment 151711 [details] [review]
Bug 32092: Fix uninitialized value in addition

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 24 Jonathan Druart 2023-07-07 09:04:03 UTC
There are failing tests, at least:
t/db_dependent/Circulation/Branch.t
t/db_dependent/Circulation/TooMany.t
Comment 25 Kyle M Hall 2023-07-07 12:23:11 UTC
Created attachment 153168 [details] [review]
Bug 32092: Improve circulation rules cache utilization

To test:
1) Go to the page for placing a hold for a biblio with a large
   number of items
2) Depending on the number of items this page can be very slow
   to load
3) Ensure the following tests pass:
   t/db_dependent/Circulation.t
   t/db_dependent/Reserves.t
   t/db_dependent/Biblio.t
   t/db_dependent/Koha/Charges/Fees.t
   t/db_dependent/Koha/Charges/Fees.t
   t/db_dependent/Items.t
   t/db_dependent/Koha/Patron.t
   t/db_dependent/api/v1/checkouts.t
   t/db_dependent/Koha/Template/Plugin/CirculationRules.t
   t/db_dependent/Template/Plugin/CirculationRules.t
   t/db_dependent/Koha/CirculationRules.t
3) Apply the patch
4) The page loading time should now be significantly faster
5) Ensure all the tests in 3) still pass

Sponsored-by: Gothenburg University Library
Signed-off-by: Emily Lamancusa <emily.lamancusa@montgomerycountymd.gov>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 26 Kyle M Hall 2023-07-07 12:23:19 UTC
Created attachment 153169 [details] [review]
Bug 32092: Fix tests

Signed-off-by: Emily Lamancusa <emily.lamancusa@montgomerycountymd.gov>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 27 Kyle M Hall 2023-07-07 12:23:21 UTC
Created attachment 153170 [details] [review]
Bug 32092: Fix uninitialized value in addition

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 28 David Gustafsson 2023-10-20 15:03:52 UTC
Created attachment 157534 [details] [review]
Bug 32092: Improve circulation rules cache utilization

To test:
1) Go to the page for placing a hold for a biblio with a large
   number of items
2) Depending on the number of items this page can be very slow
   to load
3) Ensure the following tests pass:
   t/db_dependent/Circulation.t
   t/db_dependent/Reserves.t
   t/db_dependent/Biblio.t
   t/db_dependent/Koha/Charges/Fees.t
   t/db_dependent/Items.t
   t/db_dependent/Koha/Patron.t
   t/db_dependent/api/v1/checkouts.t
   t/db_dependent/Koha/Template/Plugin/CirculationRules.t
   t/db_dependent/Template/Plugin/CirculationRules.t
   t/db_dependent/Koha/CirculationRules.t
   t/db_dependent/Circulation/Branch.t
   t/db_dependent/Circulation/TooMany.t
3) Apply the patch
4) The page loading time should now be significantly faster
5) Ensure all the tests in 3) still pass

Sponsored-by: Gothenburg University Library
Signed-off-by: Emily Lamancusa <emily.lamancusa@montgomerycountymd.gov>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 29 David Gustafsson 2023-10-20 15:03:55 UTC
Created attachment 157535 [details] [review]
Bug 32092: Fix tests

Signed-off-by: Emily Lamancusa <emily.lamancusa@montgomerycountymd.gov>

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 30 David Gustafsson 2023-10-20 15:03:57 UTC
Created attachment 157536 [details] [review]
Bug 32092: Fix uninitialized value in addition

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 31 David Gustafsson 2023-10-20 15:04:00 UTC
Created attachment 157537 [details] [review]
Bug 32092: Fix regression in TooMany and some missed cases
Comment 32 David Gustafsson 2023-10-20 15:08:09 UTC
Created attachment 157551 [details] [review]
Bug 32092: Fix regression in TooMany and some missed cases
Comment 33 David Gustafsson 2023-10-20 15:14:57 UTC
Issues should now be fixed. I failed to notice that whole rule needs to be fetched in TooMany so need to bypass cache in that case. t/db_dependent/Koha/Patron.t also fails randomly (passes sometimes) because some timing issue of the test, this occurs also in master. 
'Article requests in 10 days' passes days set to 10 and a comparison is later performed with a date-object previously created, also 10 days in the past. Depending on the execution time in between it either fails or passes is my guess.
Comment 34 Matthias Le Gac 2024-01-10 18:14:12 UTC
step 3 the test Circulation.t doesn't pass.

Error : 
t/db_dependent/Circulation.t .. 17/67 
#   Failed test 'CanBookBeRenewed tests'
#   at t/db_dependent/Circulation.t line 1690.
Exception 'Koha::Exceptions::Account::UnrecognisedType' thrown 'Type of debit not recognised'
# Looks like your test exited with 255 just after 17.
t/db_dependent/Circulation.t .. Dubious, test returned 255 (wstat 65280, 0xff00)
Failed 51/67 subtests
Comment 35 David Gustafsson 2024-02-28 16:29:24 UTC
Tests pass for me, could have been some temporary regression in koha master, or some issue with local database state.