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).
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
If I understand right : Depends on Bug 29623 that created get_effective_rule_value()
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
(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.
Yes it is in current master and 22.11.x. The dependency will be useful for RMaint of < 22.11.x
Created attachment 147149 [details] [review] Bug 32092: Fix tests
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
Created attachment 147151 [details] [review] Bug 32092: Fix tests
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>
Created attachment 149783 [details] [review] Bug 32092: Fix tests Signed-off-by: Emily Lamancusa <emily.lamancusa@montgomerycountymd.gov>
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.
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
(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.
Will attach the flame graph data on monday.
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.
(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).
Created attachment 151195 [details] Before
Created attachment 151196 [details] After
Created attachment 151197 [details] [review] Bug 32092: Fix uninitialized value in addition
@Emily Lamancusa thanks for spotting the warning the previous code did not produce, this should now be fixed.
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>
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>
Created attachment 151711 [details] [review] Bug 32092: Fix uninitialized value in addition Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
There are failing tests, at least: t/db_dependent/Circulation/Branch.t t/db_dependent/Circulation/TooMany.t
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>
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>
Created attachment 153170 [details] [review] Bug 32092: Fix uninitialized value in addition Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
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>
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>
Created attachment 157536 [details] [review] Bug 32092: Fix uninitialized value in addition Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Created attachment 157537 [details] [review] Bug 32092: Fix regression in TooMany and some missed cases
Created attachment 157551 [details] [review] Bug 32092: Fix regression in TooMany and some missed cases
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.
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
Tests pass for me, could have been some temporary regression in koha master, or some issue with local database state.