Bug 13690 - Koha::Schema should be lazy-loaded
Summary: Koha::Schema should be lazy-loaded
Status: CLOSED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: Architecture, internals, and plumbing (show other bugs)
Version: master
Hardware: All All
: P5 - low major (vote)
Assignee: Jonathan Druart
QA Contact: Testopia
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2015-02-10 14:58 UTC by Jonathan Druart
Modified: 2016-03-04 08:58 UTC (History)
8 users (show)

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


Attachments
Bug 13690: use Koha::Schema only when it's needed (834 bytes, patch)
2015-02-10 15:04 UTC, Jonathan Druart
Details | Diff | Splinter Review
Perf differences between 3.16 and 3.18 (22.73 KB, image/png)
2015-02-10 16:40 UTC, Jonathan Druart
Details
[SIGNED OFF] Bug 13690: use Koha::Schema only when it's needed (1.43 KB, patch)
2015-02-17 04:01 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
[PASSED QA] Bug 13690: use Koha::Schema only when it's needed (1.50 KB, patch)
2015-02-20 14:36 UTC, Kyle M Hall
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Jonathan Druart 2015-02-10 14:58:47 UTC

    
Comment 1 Jonathan Druart 2015-02-10 15:04:38 UTC Comment hidden (obsolete)
Comment 2 Jonathan Druart 2015-02-10 16:38:50 UTC
Some users have the feeling that 3.18.x is slower than 3.18.x
I tried to prove that.

I have created a selenium script (see bug 13691) which:
- goes on the mainpage and processes a log in (main)
- creates a patron category (add patron category)
- creates a patron (add patron)
- adds 3 items (add items)
- checks the 3 items out to the patron (checkout)
- checks the 3 items in (checkin)

On 3.18.x, the execution of the script takes ~65sec against 50sec on 3.16.x
But looking at the detailed times, the difference is much more important.
(Note that the values are the same for master and 3.18.x)

Here is the time spent for each operation
=3.18=
CP main                 = 4.04 + 4.52 + 3.86 + 4.17     => 4.15
CP add patron category  = 5.87 + 5.75 + 5.84 + 6.64     => 6.02
CP add patron           = 7.71 + 6.84 + 7.31 + 8.15     => 7.5
CP add items            = 15.08 + 15.47 + 15.09 + 14.82 => 15.12
CP checkout             = 13.31 + 14.00 + 13.63 + 13.93 => 13.72
CP checkin              = 11.78 + 12.70 + 12.81 + 11.71 => 12.25

=3.16=
CP main                 = 2.73 + 2.64 + 2.74 + 2.78 + 2.70      => 2.72
CP add patron category  = 3.93 + 3.76 + 3.82 + 3.85 + 3.78      => 3.83
CP add patron           = 5.44 + 5.12 + 5.37 + 5.18 + 5.15      => 5.25
CP add items            = 10.82 + 10.90 + 10.34 + 11.44 + 10.64 => 10.83
CP checkout             = 14.18 + 13.49 + 13.60 + 13.35 + 15.58 => 14.04
CP checkin              = 8.32 + 8.30 + 8.50 + 8.17 + 8.28      => 8.31

# Difference between both version
# diff ((3.18-3.16)/3.16)*100
CP main = +53%
CP add patron category = +57%
CP add patron = +43%
CP add items = +40%
CP checkout = -2%
CP checkin = +47%

Now, I would like to know if the patch I submitted on bug 13645 (Bug 13645: Cache the DBIx connection) is useful or not, repeat again

=3.18+13645=
CP main                = 4.20 + 4.15 + 4.42 + 4.06 + 4.52      => 4.3
CP add patron category = 6.01 + 5.89 + 5.92 + 5.78 + 6.32      =>  6
CP add patron          = 7.02 + 7.79 + 7.06 + 6.80 + 7.30      => 7.2
CP add items           = 15.34 + 15.10 + 15.31 + 16.89 + 17.03 => 15.9
CP checkout            = 15.35 + 14.01 + 14.14 + 14.07 + 14.08 => 14.3
CP checkin             = 14.38 + 11.85 + 11.86 + 12.17 + 12.17 => 12.5

Quite the same as without the patch, even a bit worse...

I would like to understand what is the difference (4.15 vs 2.72) for the main page.

Go to see the apache access logs for the GET + POST on the main page:
3.16
"GET /cgi-bin/koha/mainpage.pl HTTP/1.1" 200 2233 time=738896
"POST /cgi-bin/koha/mainpage.pl HTTP/1.1" 200 3675 time=763546

3.18
"GET /cgi-bin/koha/mainpage.pl HTTP/1.1" 200 2285 time=1374552
"POST /cgi-bin/koha/mainpage.pl HTTP/1.1" 200 3836 time=1381786

So NYTProf should help us, comparing the profiling between 3.16 and 3.18.

$ git checkout 3.16.x;rm -r /tmp/home;perl -d:NYTProf mainpage.pl
Profile of mainpage.pl for 185ms (of 258ms), executing 62528 statements and 9841 subroutine calls in 89 source files and 24 string evals.

$ git checkout 3.18.x;rm -r /tmp/home;perl -d:NYTProf mainpage.pl
Profile of mainpage.pl for 209ms (of 276ms), executing 63812 statements and 9444 subroutine calls in 81 source files and 23 string evals.
Not really...

With wget, I can reproduce the difference easily.
$ time wget http://pro.koha-qa.vm/cgi-bin/koha/mainpage.pl
3.16 ~700ms
3.18 ~1300-1400ms

Now that it's easy to reproduce the difference, I will try to find the first bad commit with git bisect:
$ git checkout 3.18.x
$ git bisect start HEAD 50078d04c6c3e3e85d6f8ed3645368f7a69402e5
$ time perl mainpage.pl

=> 1a737dcee6f600fc9d853f7318e1591b75b1349b is the first bad commit

$ git show 1a737dcee6f600fc9d853f7318e1591b75b1349b
  commit 1a737dcee6f600fc9d853f7318e1591b75b1349b
  Date:   Thu Dec 5 07:35:00 2013 -0500
      Bug 6254: make it possible to set default privacy setting for new patrons

I suspect it's because C4::Members now uses Koha::Database which uses Koha::Schema

I comment Koha::Database l.12
  #__PACKAGE__->load_namespaces;

$ time wget http://pro.koha-qa.vm/cgi-bin/koha/mainpage.pl
  returns ~700ms

So 700ms more spent in the mainpage is caused by the DBIx::Class schema loading.
But the DBIC schema is not used in the mainpage...

Try the second patch on bug 13645 (Bug 13645: Use DBIx::Connector)
$ git checkout 3.18
$ git apply patches 1, 2
$ git log --oneline
 e64240b Bug 13645: Use DBIx::Connector
 73f3835 Bug 13645: Cache the DBIx connection

CP main                = 4.06 + 4.11 + 4.09 + 4.18 + 4.32      => 4.2
CP add patron category = 5.86 + 5.77 + 5.70 + 6.15 + 5.85      => 5.9
CP add patron          = 6.88 + 7.30 + 7.47 + 6.58 + 6.56      => 7
CP add items           = 15.47 + 15.42 + 14.75 + 14.71 + 15.04 => 15.1
CP checkout            = 13.18 + 13.20 + 13.35 + 13.25 + 13.16 => 13.2
CP checkin             = 11.77 + 11.83 + 11.80 + 11.94 + 11.76 => 11.8

A bit better, but no important improvement.

Let's try to use it only if needed (Bug 13690: use Koha::Schema only when it's needed).

3 patches will be tested:
patch 1: Bug 13645: Cache the DBIx connection
patch 2: Bug 13645: Use DBIx::Connector
patch 3: Bug 13690: use Koha::Schema only when it's needed

$ git checkout 3.18.x
$ git apply patches 1, 2, 3
$ git log --oneline
 ad54b4c Bug 13690: use Koha::Schema only when it's needed
 e64240b Bug 13645: Use DBIx::Connector
 73f3835 Bug 13645: Cache the DBIx connection

CP main                = 2.70 + 2.91 + 2.72 + 2.76 + 2.84      => 2.8
CP add patron category = 3.97 + 3.81 + 4.01 + 3.84 + 4.08      => 3.9
CP add patron          = 7.01 + 5.91 + 5.88 + 6.51 + 6.31      => 6.3
CP add items           = 11.59 + 11.10 + 11.12 + 11.00 + 11.05 => 11.2
CP checkout            = 13.71 + 13.67 + 13.25 + 13.19 + 13.23 => 13.4
CP checkin             = 8.38 + 8.53 + 8.21 + 8.16 + 8.06      => 8.3

Ok we absolutely need the patch 3.

What's happen with only patch 3 applied?
it checkout 3.18
git apply patch 3
git log --oneline
 4ca93b1 Bug 13690: use Koha::Schema only when it's needed

CP main                = 2.87 + 2.86 + 2.67 + 2.76 + 2.67      => 2.8
CP add patron category = 4.16 + 3.81 + 3.78 + 4.02 + 3.82      => 3.9
CP add patron          = 6.65 + 6.32 + 6.00 + 6.14 + 6.20      => 6.3
CP add items           = 10.93 + 11.08 + 11.61 + 10.92 + 11.10 => 11.1
CP checkout            = 13.24 + 13.03 + 13.06 + 13.81 + 13.74 => 13.4
CP checkin             = 8.24 + 8.07 + 8.63 + 8.16 + 8.19      => 8.3

So this patch 3 looks sufficient, but the selenium script almost does not used parts of Koha where DBIx::Class is implemented.

If I cross these results with the ones on bug 13645 (especially comment 11):
$ git checkout master (BACK ON MASTER)
$ time perl benchmark_bookseller.pl # this script is available on bug 13645 comment 7
 perl benchmark_bookseller.pl  35.66s user 0.14s system 99% cpu 35.977.

$ git apply patch 3
$ git log --oneline
 e2a1558 Bug 13690: use Koha::Schema only when it's needed
$ time perl benchmark_bookseller.pl
 perl benchmark_bookseller.pl  34.03s user 0.15s system 99% cpu 34.241 total

This patch 3 is not enough if DBIx:Class is used.

git checkout master
$ git apply patch 1, 2, 3
$ git log --oneline
e2a1558 Bug 13690: use Koha::Schema only when it's needed
72facc6 Bug 13645: Use DBIx::Connector
3397a58 Bug 13645: Cache the DBIx connection

$ time perl benchmark_bookseller.pl
 perl benchmark_bookseller.pl  2.43s user 0.06s system 96% cpu 2.585 total
 perl benchmark_bookseller.pl  2.45s user 0.06s system 96% cpu 2.599 total
 perl benchmark_bookseller.pl  2.45s user 0.06s system 96% cpu 2.592 total
 perl benchmark_bookseller.pl  2.48s user 0.08s system 96% cpu 2.663 total
 perl benchmark_bookseller.pl  2.50s user 0.08s system 96% cpu 2.679 total

With 3 patches applied, it seems that the performances are highly better.
They globally reach the same time as 3.16.x

And... with Plack?
=3.18 + Plack=
CP main                = 1.86 + 2.16 + 1.81 + 1.66 + 2.26 => 2
CP add patron category = 2.23 + 2.10 + 2.32 + 2.25 + 2.17 => 2.2
CP add patron          = 3.27 + 2.89 + 3.17 + 3.29 + 3.38 => 3.2
CP add items           = 8.50 + 8.75 + 8.45 + 8.05 + 8.00 => 8.4
CP checkout            = 6.76 + 6.26 + 5.74 + 6.79 + 6.16 => 6.3
CP checkin             = 4.80 + 5.35 + 4.82 + 5.60 + 5.44 => 5.2

Whaou, cool :)

What about these patches?
Comment 3 Jonathan Druart 2015-02-10 16:40:22 UTC
Created attachment 35808 [details]
Perf differences between 3.16 and 3.18
Comment 4 Chris Cormack 2015-02-10 18:58:14 UTC
Looks good to me Jonathan.

As long as we get no regressions in functions, I think we should push these patches.

I might try to get them into 3.18.4 if QA is happy no regressions.
Comment 5 Brendan Gallagher 2015-02-11 06:01:54 UTC
I'm wondering if you could make a copy of your database available and the selenium test?  I can grab a copy when I am there for hackfest.  It would be nice to try some of these same tests.  I really need to spend the time to get myself some selenium tests set up.

Or did we have a place that we were placing selenium tests before?
Comment 6 Magnus Enger 2015-02-11 08:02:59 UTC
(In reply to Brendan Gallagher from comment #5)
> Or did we have a place that we were placing selenium tests before?

There are some in the selenium dir:
http://git.koha-community.org/gitweb/?p=koha.git;a=tree;f=selenium;hb=HEAD

These were added by HDL 5-6 years ago and have not been maintained. Jonathan is suggesting we replace them with new ones on bug 13691, which is awesome! Koha could really benefit from some integration tests, imho.
Comment 7 Jonathan Druart 2015-02-11 08:30:29 UTC
Yep, as Magnus said :)
And I would add that you can launch the selenium tests using any DB (in theory, I did not try!).
Comment 8 Paul Poulain 2015-02-11 11:32:20 UTC
(In reply to Jonathan Druart from comment #2)
> And... with Plack?
> =3.18 + Plack=
> CP main                = 1.86 + 2.16 + 1.81 + 1.66 + 2.26 => 2
> CP add patron category = 2.23 + 2.10 + 2.32 + 2.25 + 2.17 => 2.2
> CP add patron          = 3.27 + 2.89 + 3.17 + 3.29 + 3.38 => 3.2
> CP add items           = 8.50 + 8.75 + 8.45 + 8.05 + 8.00 => 8.4
> CP checkout            = 6.76 + 6.26 + 5.74 + 6.79 + 6.16 => 6.3
> CP checkin             = 4.80 + 5.35 + 4.82 + 5.60 + 5.44 => 5.2
> 
> Whaou, cool :)
3.18 with Plack and this patch or without this patch ?

(next step according to me: improve checkout !
Comment 9 Jonathan Druart 2015-02-11 11:43:33 UTC
(In reply to Paul Poulain from comment #8)
> (In reply to Jonathan Druart from comment #2)
> > And... with Plack?
> > =3.18 + Plack=
> > CP main                = 1.86 + 2.16 + 1.81 + 1.66 + 2.26 => 2
> > CP add patron category = 2.23 + 2.10 + 2.32 + 2.25 + 2.17 => 2.2
> > CP add patron          = 3.27 + 2.89 + 3.17 + 3.29 + 3.38 => 3.2
> > CP add items           = 8.50 + 8.75 + 8.45 + 8.05 + 8.00 => 8.4
> > CP checkout            = 6.76 + 6.26 + 5.74 + 6.79 + 6.16 => 6.3
> > CP checkin             = 4.80 + 5.35 + 4.82 + 5.60 + 5.44 => 5.2
> > 
> > Whaou, cool :)
> 3.18 with Plack and this patch or without this patch ?

It's 3.18.x and Plack, so without any other patches applied.
Comment 10 Kyle M Hall 2015-02-11 11:47:05 UTC
If these patches don't cause any regressions I see absolutely no reason why we shouldn't not get these changes into master. Great sleuthing Jonathan!
Comment 11 Paul Poulain 2015-02-11 11:57:06 UTC
(In reply to Jonathan Druart from comment #9)
> > 3.18 with Plack and this patch or without this patch ?
> 
> It's 3.18.x and Plack, so without any other patches applied.
What about results with 3.18+Plack+your patches ?
Comment 12 Jonathan Druart 2015-02-11 13:51:43 UTC
(In reply to Paul Poulain from comment #11)
> (In reply to Jonathan Druart from comment #9)
> > > 3.18 with Plack and this patch or without this patch ?
> > 
> > It's 3.18.x and Plack, so without any other patches applied.
> What about results with 3.18+Plack+your patches ?

=3.18 + Plack + patches 1, 2, 3=
CP main                = 1.64 + 1.59 + 1.61 + 1.59 + 1.53 => 1.6 
CP add patron category = 2.48 + 2.21 + 2.07 + 2.07 + 2.20 => 2.2 
CP add patron          = 2.73 + 2.62 + 2.69 + 2.63 + 2.66 => 2.7 
CP add items           = 7.89 + 7.96 + 7.82 + 8.08 + 7.91 => 7.9 
CP checkout            = 5.29 + 5.77 + 4.96 + 5.42 + 5.39 => 5.3 
CP checkin             = 4.92 + 4.78 + 5.90 + 4.99 + 5.45 => 5.2
Comment 13 Jonathan Druart 2015-02-12 09:18:13 UTC
Switch the status to Needs Signoff.
Comment 14 Paul Poulain 2015-02-12 09:32:32 UTC
Calculated sums :
 * 3.18 + Plack without those patches : 27.3s
 * 3.18 + Plack with those patches: 24.9

(compared to 65 for 3.18 and 50 for 3.16 in CGI mode)
Comment 15 Tomás Cohen Arazi 2015-02-17 04:01:47 UTC Comment hidden (obsolete)
Comment 16 Kyle M Hall 2015-02-20 14:36:59 UTC
Created attachment 36088 [details] [review]
[PASSED QA] Bug 13690: use Koha::Schema only when it's needed

This patch makes Koha::Database lazy-load the whole Koha::Schema libraries.
It doesn't seem to have negative effects, and makes scripts not using
DBIx::Class notably faster [1].

Regards

[1] If you read the DBIx::Class::Schema docs, it explains that it it uses
Module::Find to load all schema files...
http://search.cpan.org/~ribasushi/DBIx-Class-0.082810/lib/DBIx/Class/Schema.pm#load_namespaces

Signed-off-by: Tomas Cohen Arazi <tomascohen@gmail.com>
Happy to sign this one. The only extra comment would be that DBIx::Class
performance issues remain after this patch, but is being handled in a
different bug.

Signed-off-by: Kyle M Hall <kyle@bywatersolutions.com>
Comment 17 Tomás Cohen Arazi 2015-02-20 14:52:54 UTC
Patch pushed to master.

Thanks a lot Jonathan!
Comment 18 Chris Cormack 2015-02-22 23:14:21 UTC
Pushed to 3.18.x will be in 3.18.4