Bug 18821

Summary: TrackLastPatronActivity is a performance killer
Product: Koha Reporter: Kyle M Hall <kyle>
Component: Architecture, internals, and plumbingAssignee: Kyle M Hall <kyle>
Status: CLOSED FIXED QA Contact: Marcel de Rooy <m.de.rooy>
Severity: major    
Priority: P5 - low CC: alexbuckley, charles.farmer, fridolin.somers, jonathan.druart, julian.maurice, katrin.fischer, ldjamison, m.de.rooy, martin.renvoize, mtompset, nick, nicolas.legrand, paul.poulain, sally.healey
Version: Main   
Hardware: All   
OS: All   
Change sponsored?: --- Patch complexity: Small patch
Documentation contact: Documentation submission:
Text to go in the release notes:
Version(s) released in:
Bug Depends on: 16276    
Bug Blocks:    
Attachments: Bug 18821 - GetPatronLastActivity is a performance killer
Bug 18821 - GetPatronLastActivity is a performance killer
Bug 18821 - TrackLastPatronActivity is a performance killer
Bug 18821 - TrackLastPatronActivity is a performance killer
Bug 18821: [DO NOT PUSH] Print STDERR Scaffolding
Bug 18821 [QA Followup]: Add additional unit tests for completeness
Bug 18821 - TrackLastPatronActivity is a performance killer
Bug 18821: [DO NOT PUSH] Print STDERR Scaffolding
Bug 18821 [QA Followup]: Add additional unit tests for completeness
Bug 18821 - TrackLastPatronActivity is a performance killer
Bug 18821 - TrackLastPatronActivity is a performance killer
Bug 18821 - (follow-up) adds POD to track_login_for_session, removes tab in Auth.t
Bug 18821 - Flush session after setting tracked_for_session
Bug 18821 - TrackLastPatronActivity is a performance killer
Bug 18821: Convert to using cache with date checking
Bug 18821: TrackLastPatronActivity is a performance killer
Bug 18821: Convert to using cache with date checking
Bug 18821: TrackLastPatronActivity is a performance killer
Bug 18821: Convert to using cache with date checking
Bug 18821: (QA follow-up) Last tweaks for performance
Bug 18821: (QA follow-up) Last tweaks for performance

Description Kyle M Hall 2017-06-19 13:48:30 UTC
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.
Comment 1 Kyle M Hall 2017-06-19 13:52:24 UTC
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
Comment 2 Kyle M Hall 2017-06-19 13:53:12 UTC
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
Comment 3 Lee Jamison 2017-06-22 16:18:26 UTC
For posterity the correct System Preference name is "TrackLastPatronActivity".
Comment 4 Kyle M Hall 2017-08-08 18:27:35 UTC
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
Comment 5 Alex Buckley 2017-09-09 19:49:35 UTC
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
Comment 6 Kyle M Hall 2018-03-23 13:12:17 UTC
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
Comment 7 Mark Tompsett 2018-04-05 16:57:53 UTC
Fails to trigger changed code. Attaching print STDERR scaffolding. Auth 3 and Auth 4.
Comment 8 Mark Tompsett 2018-04-05 17:00:20 UTC
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
Comment 9 Kyle M Hall 2018-04-09 12:40:14 UTC
Created attachment 73863 [details] [review]
Bug 18821 [QA Followup]: Add additional unit tests for completeness
Comment 10 Mark Tompsett 2018-04-09 19:25:46 UTC
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>
Comment 11 Mark Tompsett 2018-04-09 19:25:49 UTC
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>
Comment 12 Mark Tompsett 2018-04-09 19:25:52 UTC
Created attachment 73893 [details] [review]
Bug 18821 [QA Followup]: Add additional unit tests for completeness

Signed-off-by: Mark Tompsett <mtompset@hotmail.com>
Comment 13 Mark Tompsett 2018-04-09 19:27:05 UTC
Tests trigger all changed code. Thanks, Kyle. :)
Comment 14 Kyle M Hall 2018-04-10 12:46:38 UTC
(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!
Comment 15 Jonathan Druart 2018-04-23 18:23:25 UTC
I am not against the patch, but it's hard to imagine that 1 update query by request can be a  "performance killer".
Comment 16 Mark Tompsett 2018-04-23 18:46:33 UTC
(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.
Comment 17 Kyle M Hall 2018-04-27 10:07:39 UTC
(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!
Comment 18 Julian Maurice 2018-04-30 13:06:00 UTC
(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
Comment 19 Katrin Fischer 2018-05-04 05:39:48 UTC
Please take a look at the last comment!
Comment 20 Kyle M Hall 2018-05-07 17:30:42 UTC
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
Comment 21 Kyle M Hall 2018-05-07 17:34:37 UTC
> 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!
Comment 22 Charles Farmer 2018-05-11 20:31:07 UTC
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>
Comment 23 Charles Farmer 2018-05-11 20:31:34 UTC
Created attachment 75289 [details] [review]
Bug 18821 - (follow-up) adds POD to track_login_for_session, removes tab in Auth.t
Comment 24 Charles Farmer 2018-05-11 20:34:28 UTC
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.
Comment 25 Charles Farmer 2018-05-11 20:36:50 UTC Comment hidden (obsolete)
Comment 26 Charles Farmer 2018-05-11 20:49:03 UTC Comment hidden (obsolete)
Comment 27 Kyle M Hall 2018-05-14 12:09:33 UTC
Thanks for the followup Charles!
Comment 28 Marcel de Rooy 2018-05-18 05:59:28 UTC
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)?
Comment 29 Kyle M Hall 2018-05-18 12:40:51 UTC
Created attachment 75427 [details] [review]
Bug 18821 - Flush session after setting tracked_for_session
Comment 30 Marcel de Rooy 2018-05-25 07:36:40 UTC
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..)
Comment 31 Kyle M Hall 2018-05-25 14:31:34 UTC
> 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.
Comment 32 Jonathan Druart 2018-05-28 12:50:19 UTC
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.
Comment 33 Kyle M Hall 2018-05-29 12:09:17 UTC
(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?
Comment 34 Marcel de Rooy 2018-05-29 12:12:41 UTC
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 ?
Comment 35 Kyle M Hall 2018-05-29 13:58:59 UTC
(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.
Comment 36 Kyle M Hall 2018-05-29 14:03:28 UTC
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 ).
Comment 37 Kyle M Hall 2018-05-29 14:07:00 UTC
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>
Comment 38 Kyle M Hall 2018-05-29 14:07:10 UTC
Created attachment 75633 [details] [review]
Bug 18821: Convert to using cache with date checking
Comment 39 Kyle M Hall 2018-05-29 14:08:13 UTC
Created attachment 75634 [details] [review]
Bug 18821: TrackLastPatronActivity is a performance killer
Comment 40 Kyle M Hall 2018-05-29 14:08:21 UTC
Created attachment 75635 [details] [review]
Bug 18821: Convert to using cache with date checking
Comment 41 Marcel de Rooy 2018-06-01 07:44:09 UTC
QA: Having another look here
Comment 42 Marcel de Rooy 2018-06-01 09:14:08 UTC
(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!
Comment 43 Marcel de Rooy 2018-06-01 09:14:49 UTC
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>
Comment 44 Marcel de Rooy 2018-06-01 09:14:54 UTC
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>
Comment 45 Marcel de Rooy 2018-06-01 09:15:00 UTC
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.
Comment 46 Kyle M Hall 2018-06-01 10:46:58 UTC
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>
Comment 47 Nick Clemens 2018-06-08 13:58:07 UTC
Pushed to master for 18.11, awesome work all!
Comment 48 Martin Renvoize 2018-06-11 08:06:10 UTC
This patch has been pushed to 18.05.x and will be in 18.05.01

Be nice to see this performance improvement :)
Comment 49 Fridolin Somers 2018-06-26 07:45:22 UTC
Pushed to 17.11.x for 17.11.07
Comment 50 Fridolin Somers 2018-06-26 07:47:40 UTC
Pushed to 17.05.x for 17.05.13