[Koha-bugs] [Bug 13690] 3.18 performance issues
bugzilla-daemon at bugs.koha-community.org
bugzilla-daemon at bugs.koha-community.org
Tue Feb 10 17:38:50 CET 2015
http://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=13690
Jonathan Druart <jonathan.druart at biblibre.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|ASSIGNED |In Discussion
--- Comment #2 from Jonathan Druart <jonathan.druart at biblibre.com> ---
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?
--
You are receiving this mail because:
You are watching all bug changes.
More information about the Koha-bugs
mailing list