Enabling GetPatronLastActivity can cause an extreme performance hit, especially on the staff side during checkin and checkout. It makes more sense to only update the last activity timestamp on the first access of a given session. This will greatly improve performance while retaining the same basic information.
Created attachment 64425 [details] [review] Bug 18821 - GetPatronLastActivity is a performance killer Enabling GetPatronLastActivity can cause an extreme performance hit, especially on the staff side during checkin and checkout. It makes more sense to only update the last activity timestamp on the first access of a given session. This will greatly improve performance while retaining the same basic information. Test Plan: 1) Apply this patch 2) Start a new session ( a private browser window works well ) 3) Note the lastseen column in the borrowers table is updated 4) Browse a few pages, not the lastseen column is not updated again 5) Close the browser window and repeat steps 2-4 6) prove t/db_dependent/Members.t
Created attachment 64426 [details] [review] Bug 18821 - GetPatronLastActivity is a performance killer Enabling GetPatronLastActivity can cause an extreme performance hit, especially on the staff side during checkin and checkout. It makes more sense to only update the last activity timestamp on the first access of a given session. This will greatly improve performance while retaining the same basic information. Test Plan: 1) Apply this patch 2) Start a new session ( a private browser window works well ) 3) Note the lastseen column in the borrowers table is updated 4) Browse a few pages, not the lastseen column is not updated again 5) Close the browser window and repeat steps 2-4 6) prove t/db_dependent/Members.t
For posterity the correct System Preference name is "TrackLastPatronActivity".
Created attachment 65687 [details] [review] Bug 18821 - TrackLastPatronActivity is a performance killer Enabling TrackLastPatronActivity can cause an extreme performance hit, especially on the staff side during checkin and checkout. It makes more sense to only update the last activity timestamp on the first access of a given session. This will greatly improve performance while retaining the same basic information. Test Plan: 1) Apply this patch 2) Start a new session ( a private browser window works well ) 3) Note the lastseen column in the borrowers table is updated 4) Browse a few pages, not the lastseen column is not updated again 5) Close the browser window and repeat steps 2-4 6) prove t/db_dependent/Members.t
Hi Kyle Testing your patch on kohadevbox I am finding that the lastseen column is updated everytime I browse a page even though the test plan says it shouldn't
Created attachment 73175 [details] [review] Bug 18821 - TrackLastPatronActivity is a performance killer Enabling TrackLastPatronActivity can cause an extreme performance hit, especially on the staff side during checkin and checkout. It makes more sense to only update the last activity timestamp on the first access of a given session. This will greatly improve performance while retaining the same basic information. Test Plan: 1) Apply this patch 2) Start a new session ( a private browser window works well ) 3) Note the lastseen column in the borrowers table is updated 4) Browse a few pages, not the lastseen column is not updated again 5) Close the browser window and repeat steps 2-4 6) prove t/db_dependent/Members.t
Fails to trigger changed code. Attaching print STDERR scaffolding. Auth 3 and Auth 4.
Created attachment 73706 [details] [review] Bug 18821: [DO NOT PUSH] Print STDERR Scaffolding Tests must trigger all STDERRs added. prove t/db_dependent/Members.t prove t/db_dependent/Auth.t Patrons 3 and 4 not triggered. Current status: Failed QA
Created attachment 73863 [details] [review] Bug 18821 [QA Followup]: Add additional unit tests for completeness
Created attachment 73891 [details] [review] Bug 18821 - TrackLastPatronActivity is a performance killer Enabling TrackLastPatronActivity can cause an extreme performance hit, especially on the staff side during checkin and checkout. It makes more sense to only update the last activity timestamp on the first access of a given session. This will greatly improve performance while retaining the same basic information. Test Plan: 1) Apply this patch 2) Start a new session ( a private browser window works well ) 3) Note the lastseen column in the borrowers table is updated 4) Browse a few pages, not the lastseen column is not updated again 5) Close the browser window and repeat steps 2-4 6) prove t/db_dependent/Members.t Signed-off-by: Mark Tompsett <mtompset@hotmail.com>
Created attachment 73892 [details] [review] Bug 18821: [DO NOT PUSH] Print STDERR Scaffolding Tests must trigger all STDERRs added. prove t/db_dependent/Members.t prove t/db_dependent/Auth.t Patrons 3 and 4 not triggered. Signed-off-by: Mark Tompsett <mtompset@hotmail.com>
Created attachment 73893 [details] [review] Bug 18821 [QA Followup]: Add additional unit tests for completeness Signed-off-by: Mark Tompsett <mtompset@hotmail.com>
Tests trigger all changed code. Thanks, Kyle. :)
(In reply to M. Tompsett from comment #13) > Tests trigger all changed code. Thanks, Kyle. :) Thanks for the catch! I think we can deprecate your scaffolding patch now!
I am not against the patch, but it's hard to imagine that 1 update query by request can be a "performance killer".
(In reply to Jonathan Druart from comment #15) > I am not against the patch, but it's hard to imagine that 1 update query by > request can be a "performance killer". I think it may be because the value wasn't persistent, so it was always being queried.
(In reply to M. Tompsett from comment #16) > (In reply to Jonathan Druart from comment #15) > > I am not against the patch, but it's hard to imagine that 1 update query by > > request can be a "performance killer". > > I think it may be because the value wasn't persistent, so it was always > being queried. Indeed, on a busy system we've seen this slow down servers quite dramatically!
(In reply to Jonathan Druart from comment #15) > I am not against the patch, but it's hard to imagine that 1 update query by > request can be a "performance killer". For me the patch saves approximately 4ms per request. Not the huge performance boost I expected by reading the bug title but it does save some time. It should be noted that in the syspref description we can read > Everytime a patron will connect, the borrowers.lastseen will be updated with the current time "connect" might be interpreted in different ways but I think what most people understand is that a connection is when a user types their credentials in order to be logged in the application, and not when the user is automatically logged in by a session cookie. So the patch actually makes Koha behaviour closer to the syspref description. However, I don't like the way it is done. Passing the CGI::Session object to a Koha::Patron method so it can read it and write to it. I think "Koha::Object"s methods shouldn't be aware of what we use to manage the session. Instead we should call track_login only when needed, like for example just after a successful login : https://gitlab.com/koha-community/Koha/blob/e5d5038fa3a1fbfaf81f4b01d319b00af5a7c46c/C4/Auth.pm#L1161
Please take a look at the last comment!
Created attachment 75139 [details] [review] Bug 18821 - TrackLastPatronActivity is a performance killer Test Plan: 1) Apply this patch 2) Start a new session ( a private browser window works well ) 3) Note the lastseen column in the borrowers table is updated 4) Browse a few pages, not the lastseen column is not updated again 5) Close the browser window and repeat steps 2-4 6) prove t/db_dependent/Auth.t
> However, I don't like the way it is done. Passing the CGI::Session object to > a Koha::Patron method so it can read it and write to it. I think > "Koha::Object"s methods shouldn't be aware of what we use to manage the > session. That seems like a reasonable request. Please take a look at the new edition of the patch and sign off if you can!
Created attachment 75288 [details] [review] Bug 18821 - TrackLastPatronActivity is a performance killer Test Plan: 1) Apply this patch 2) Start a new session ( a private browser window works well ) 3) Note the lastseen column in the borrowers table is updated 4) Browse a few pages, not the lastseen column is not updated again 5) Close the browser window and repeat steps 2-4 6) prove t/db_dependent/Auth.t Signed-off-by: Charles Farmer <charles.farmer@inLibro.com>
Created attachment 75289 [details] [review] Bug 18821 - (follow-up) adds POD to track_login_for_session, removes tab in Auth.t
The patch does as described in the test plan, that is to only update the lastseen field on login, but when looking at the Apache log, the time taken to serve a page is pretty much the same. Could more information be provided on the techniques used to bench the code? Are you running a mysql_general_log alongside to better compare? Using ab (apache benchmarks)? Otherwise, now that there's an additional (follow-up) patch, it should pass `qa -c 2`, prove, and as Julian said, it makes TrackLastPatronActivity behave more closely the 'common sense' interpretation of its description. I feel confident signing this off.
Forgot to post a question in my last message: how come track_login_for_session's inside EXPORTER_OK? Does it make sense to use it anywhere else than inside C4/Auth.pm?
Never mind my last comment, it wouldn't be testable at the function level under t/ otherwise.
Thanks for the followup Charles!
Are we trusting on autoflush to save the session data? I saw that the date was updated a second time while being in the same session. Do we need a specific session flush (especially under Plack)?
Created attachment 75427 [details] [review] Bug 18821 - Flush session after setting tracked_for_session
This unfortunately is not enough. We have to deal here with the wonderous CGI::Session object ;) Test this: Remove all sessions. Login. Now check sessions again. You have 5 entries. 1 entry contains the info about the logged in user. You should expect the new track param here too. But it is not there. What happens? Somehow $session is already undef when you call track. If we need to call CGI::Session->new($sessionID) each time, we do not really benefit in terms of db access (well: 1 lookup in sessions instead of 1 in borrowers). Is there a different approach? What about using a cache key? (Do we want to pollute the cache with keys for every session..)
> What happens? Somehow $session is already undef when you call track. If we > need to call CGI::Session->new($sessionID) each time, we do not really > benefit in terms of db access (well: 1 lookup in sessions instead of 1 in > borrowers). That would at least be changing from 1 write to 1 read, which is definitely an improvement, right? > Is there a different approach? What about using a cache key? (Do we want to > pollute the cache with keys for every session..) So you're suggesting storing something like -- my $cache = Koha::Caches->get_instance(); my $cache_key = "seen-for-session-$borrowernumber"; my $cached = $cache->get_from_cache($cache_key, { unsafe => 1}); unless ( $cached ) { $patron->track_login; $cache->set_in_cache($cache_key, 1); } -- If so, I think that works! Let me know and I'll submit a patch.
Before continuing here I think we should first confirm that the code is the cause of the problem. I have talked with Nick last month and it seemed that it came from somewhere else: """ Errors in the logs "DBD::mysql::db begin_work failed: Already in a transaction" - it seemed to increase during heavy circ periods - DB was slowed by constant hits and then clashes """ It does not sound related to this code, but more to rebuild_zebra.pl that uses AutoCommit instead of a DBIC transaction.
(In reply to Jonathan Druart from comment #32) > Before continuing here I think we should first confirm that the code is the > cause of the problem. > > I have talked with Nick last month and it seemed that it came from somewhere > else: > > """ > Errors in the logs "DBD::mysql::db begin_work failed: Already in a > transaction" - it seemed to increase during heavy circ periods - DB was > slowed by constant hits and then clashes > """ > > It does not sound related to this code, but more to rebuild_zebra.pl that > uses AutoCommit instead of a DBIC transaction. While that may be true, it does not change the fact that this feature *is* a performance killer. We've seen multiple instances of slow servers that having a immediate speed improvement simply by disabling this feature! Nothing about transactions has been mentioned on this bug previously, are you sure you are commenting on the correct bug?
I think we should not use the cache here. We will just dump too much in memory. Should we change lastseen to a date and check if NOW> lastseen ? This would skip a lot of writes ?
(In reply to Marcel de Rooy from comment #34) > I think we should not use the cache here. We will just dump too much in > memory. > Should we change lastseen to a date and check if NOW> lastseen ? This would > skip a lot of writes ? I actually think a hybrid of your first and second suggestions is the best solution. We should use cache *and* test a date! Why do you think we will use too much memory? Let's assume we have 1000 simultaneous users. That's still a minuscule amount of memory compared to caching the marc frameworks, for example.
I forgot to add that this will be the fastest variation as well, since it is guaranteed to be only in memory as opposed to both session and direct db which would read and write to database or filesystem for everything ( except session => memcached which would still be slower with its added abstraction ).
Created attachment 75632 [details] [review] Bug 18821 - TrackLastPatronActivity is a performance killer Test Plan: 1) Apply this patch 2) Start a new session ( a private browser window works well ) 3) Note the lastseen column in the borrowers table is updated 4) Browse a few pages, not the lastseen column is not updated again 5) Close the browser window and repeat steps 2-4 6) prove t/db_dependent/Auth.t Signed-off-by: Charles Farmer <charles.farmer@inLibro.com>
Created attachment 75633 [details] [review] Bug 18821: Convert to using cache with date checking
Created attachment 75634 [details] [review] Bug 18821: TrackLastPatronActivity is a performance killer
Created attachment 75635 [details] [review] Bug 18821: Convert to using cache with date checking
QA: Having another look here
(In reply to Kyle M Hall from comment #35) > I actually think a hybrid of your first and second suggestions is the best > solution. We should use cache *and* test a date! Why do you think we will > use too much memory? Let's assume we have 1000 simultaneous users. That's > still a minuscule amount of memory compared to caching the marc frameworks, > for example. On second thought, the consumed cache may be very limited indeed. Nice!
Created attachment 75727 [details] [review] Bug 18821: TrackLastPatronActivity is a performance killer Test Plan: 1) Apply this patch 2) Start a new session ( a private browser window works well ) 3) Note the lastseen column in the borrowers table is updated 4) Browse a few pages, not the lastseen column is not updated again 5) Close the browser window and repeat steps 2-4 6) prove t/db_dependent/Auth.t Signed-off-by: Charles Farmer <charles.farmer@inLibro.com> Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Created attachment 75728 [details] [review] Bug 18821: Convert to using cache with date checking Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Created attachment 75729 [details] [review] Bug 18821: (QA follow-up) Last tweaks for performance [1] passing unsafe has no use since it is a scalar, removed it to unconfuse [2] remove caching when pref is disabled [3] caching userid removes the need for calling Patron->find each time [4] subsequent changes in unit test [5] cosmetic renames to move from session to daily basis (changed dev angle) Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> First call going thru Koha::Patron takes about 0.0150 sec. Subsequent calls only use caching and take about 0.0006 sec.
Created attachment 75733 [details] [review] Bug 18821: (QA follow-up) Last tweaks for performance [1] passing unsafe has no use since it is a scalar, removed it to unconfuse [2] remove caching when pref is disabled [3] caching userid removes the need for calling Patron->find each time [4] subsequent changes in unit test [5] cosmetic renames to move from session to daily basis (changed dev angle) Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl> First call going thru Koha::Patron takes about 0.0150 sec. Subsequent calls only use caching and take about 0.0006 sec. Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Pushed to master for 18.11, awesome work all!
This patch has been pushed to 18.05.x and will be in 18.05.01 Be nice to see this performance improvement :)
Pushed to 17.11.x for 17.11.07
Pushed to 17.05.x for 17.05.13