Bug 13226 - Significant slowdown of checkins with fix for notices ignoring the dateformat preference
Summary: Significant slowdown of checkins with fix for notices ignoring the dateformat...
Status: CLOSED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: Circulation (show other bugs)
Version: master
Hardware: All All
: P5 - low major (vote)
Assignee: Jonathan Druart
QA Contact: Testopia
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2014-11-07 19:01 UTC by Owen Leonard
Modified: 2015-06-04 23:33 UTC (History)
5 users (show)

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


Attachments
time checkin (268 bytes, application/x-perl)
2014-11-10 14:32 UTC, Jonathan Druart
Details
DO NOT PUSH: profiling for _parseletter (1.98 KB, patch)
2014-11-12 13:48 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 13226: 9999-12-31 should not considered as a valid date (1.24 KB, patch)
2014-11-12 16:21 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 13226: 9999-12-31 should not considered as a valid date (1.24 KB, patch)
2014-11-12 16:26 UTC, Jonathan Druart
Details | Diff | Splinter Review
[SIGNED-OFF] Bug 13226: 9999-12-31 should not considered as a valid date (1.62 KB, patch)
2014-11-12 17:03 UTC, Owen Leonard
Details | Diff | Splinter Review
[PASSED QA] Bug 13226: 9999-12-31 should not considered as a valid date (1.68 KB, patch)
2014-11-13 21:20 UTC, Katrin Fischer
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Owen Leonard 2014-11-07 19:01:18 UTC
I noticed that checkins were being processed very slowly and ran some tests. I found that before the patch for Bug 11244 checking in an item which is checked out to a restricted patron took around 2.5 seconds (as measured by Firebug's Net panel). After Bug 11244 the same type of checkin took over 50 seconds.

Checking in an item which is checked out to a patron in good standing doesn't seem to be affected.
Comment 1 David Cook 2014-11-09 22:31:35 UTC
Very interesting!

I assume that your patrons get "check in" emails? We don't do those kinds of emails so I never even thought about that happening...

Amazing that it would go from 2.5 seconds to 50 seconds though :S. That's much much higher than the worst time we recorded for generating overdues.

Olli-Antti Kivilahti processed 12 messages in 31 seconds.
I processed 35 messages in 31 seconds.

Astounding that it would be 1 message in 50 seconds.

I suppose that regex would be running over every single replaceable field. Does your check in message have a lot of fields to replace with database data?

I'm not sure how to fix this one. The regex idea seemed like the best way of dealing with the dateformat issue in notices :S.

I thought about using DBIC to check what type of field we were using, but you can't do that because many table names don't translate to DBIC resultset names. DBIC is pretty slow too though, so I don't know.

I'm fresh out of ideas on this one :(
Comment 2 Jonathan Druart 2014-11-10 09:00:13 UTC
(In reply to David Cook from comment #1)
> I suppose that regex would be running over every single replaceable field.
> Does your check in message have a lot of fields to replace with database
> data?

Yes, could you give a copy of the template letter used?

I have the default one (installer/data/mysql/en/mandatory/sample_notices.sql), I manually added a restriction to a patron, checkin, and it took the same time as before (I didn't measured precisely but not 50sec).
Comment 3 Owen Leonard 2014-11-10 13:51:00 UTC
(In reply to Jonathan Druart from comment #2)

> Yes, could you give a copy of the template letter used?

I have the default one.
Comment 4 Jonathan Druart 2014-11-10 14:32:09 UTC
Created attachment 33426 [details]
time checkin

Owen, could you execute this script like:
    time perl time_checkin.pl
and give me the result please?
Before, fill the $barcode_to_checkin and $branchcode variable with correct values.
I would like to be sure the 50sec are spent in this subroutine.

Here it spent 1sec. I check an item out to a patron, enable the CHECKIN notice for this patron and add a restriction on it.
Comment 5 Owen Leonard 2014-11-10 18:58:02 UTC
>     time perl time_checkin.pl
> and give me the result please?

real	0m51.725s
user	0m50.347s
sys	0m0.468s
Comment 6 Jonathan Druart 2014-11-12 13:48:14 UTC Comment hidden (obsolete)
Comment 7 Jonathan Druart 2014-11-12 13:49:24 UTC
You can also try to put some warns (see this patch).
Comment 8 Jonathan Druart 2014-11-12 16:21:15 UTC Comment hidden (obsolete)
Comment 9 Jonathan Druart 2014-11-12 16:26:21 UTC Comment hidden (obsolete)
Comment 10 Jonathan Druart 2014-11-12 16:39:37 UTC
It seems that this patch does not completely fix the problem.
I still have a 9999-12-31 somewhere else. But not introduced by bug 11244.

Owen could you test it please?
Comment 11 Owen Leonard 2014-11-12 16:57:39 UTC
(In reply to Jonathan Druart from comment #10)
> It seems that this patch does not completely fix the problem.

With this patch I see a significant improvement: Check-ins from the account of a patron who is restricted indefinitely have gone from taking around 50 seconds to between 7 and 10 seconds. It's still slower than the 2-3 seconds for other checkins, but much better.
Comment 12 Owen Leonard 2014-11-12 17:03:13 UTC Comment hidden (obsolete)
Comment 13 David Cook 2014-11-12 22:15:42 UTC
(In reply to Owen Leonard from comment #12)
> Note that to reproduce the problem you much be checking in items from an
> account which has been restricted indefinitely (either manually or by
> the overdues process). With this patch such checkins go from taking
> around 50 seconds (in my test system) to around 7 to 10 seconds.

Does that mean that check-ins for non-restricted patrons are processed quickly (e.g. 2-3 seconds)?
Comment 14 Jonathan Druart 2014-11-13 08:36:25 UTC
(In reply to David Cook from comment #13)
> (In reply to Owen Leonard from comment #12)
> > Note that to reproduce the problem you much be checking in items from an
> > account which has been restricted indefinitely (either manually or by
> > the overdues process). With this patch such checkins go from taking
> > around 50 seconds (in my test system) to around 7 to 10 seconds.
> 
> Does that mean that check-ins for non-restricted patrons are processed
> quickly (e.g. 2-3 seconds)?

Yes.
Comment 15 Jonathan Druart 2014-11-13 08:37:04 UTC
Owen, please have a look at bug 13242 to get rid of some other seconds.
Comment 16 Katrin Fischer 2014-11-13 21:20:49 UTC
Created attachment 33539 [details] [review]
[PASSED QA] Bug 13226: 9999-12-31 should not considered as a valid date

DateTime::Format::DateParse (called in Koha::DateUtils::dt_from_string)
does not manage to parse 9999-12-31 if a time zone is given.

my $date = DateTime->new(year => 9999, month => 12, day => 31);
 => OK

DateTime::Format::DateParse->parse_datetime( '9999-12-31' );
 => OK

DateTime::Format::DateParse->parse_datetime( '9999-12-31',
 'America/Los_Angeles' );
 => KO (~20sec on my laptop)

It should not be considered as a valid date when the letter is parsed.

Signed-off-by: Owen Leonard <oleonard@myacpl.org>

Note that to reproduce the problem you much be checking in items from an
account which has been restricted indefinitely (either manually or by
the overdues process). With this patch such checkins go from taking
around 50 seconds (in my test system) to around 7 to 10 seconds.

Signed-off-by: Katrin Fischer <Katrin.Fischer.83@web.de>

Good catch! Works as described, no problems found.
Comment 17 Tomás Cohen Arazi 2014-11-14 14:03:35 UTC
Fix pushed to master.

Thanks Jonathan!