[Koha] Slow Koha OPAC login process

[Michael Kuhn]

Hi Tomás

Thanks for your hints! You wrote:

 > output_with_http_headers is a function that calls the templates code.
 > I would bet it is an IO problem.
 >
 > Please run iotop while reproducing the problem. I would expect to see
 > some iowait.

I installed the command "iotop" and ran it when reproducing the problem. 
But it shows nothing special:

Total DISK READ :   0.00 B/s | Total DISK WRITE :       0.00 B/s
Actual DISK READ:   0.00 B/s | Actual DISK WRITE:       0.00 B/s
   TID  PRIO  USER   DISK READ  DISK WRITE SWAPIN     IO>   COMMAND
64690 be/4 root     0.00 B/s    0.00 B/s  0.00 %  0.03 % [kworker/1:2]
64000 be/4 www-data 0.00 B/s    0.00 B/s  0.00 %  0.00 % apache2 -k start
     1 be/4 root     0.00 B/s    0.00 B/s  0.00 %  0.00 % init
     2 be/4 root     0.00 B/s    0.00 B/s  0.00 %  0.00 % [kthreadd]
     3 be/4 root     0.00 B/s    0.00 B/s  0.00 %  0.00 % ksoftirqd/0]
  1540 be/4 Debian-g 0.00 B/s    0.00 B/s  0.00 %  0.00 % gnome-she~nf 
worker]
     5 be/0 root     0.00 B/s    0.00 B/s  0.00 %  0.00 % [kworker/0:0H]

 > Do you have template_cache_dir set?

I added the following line in file "koha-conf.xml" just after the two 
memcached lines:

<memcached_servers></memcached_servers>
<memcached_namespace></memcached_namespace>
<template_cache_dir>/tmp</template_cache_dir>

Then I restarted Koha. The problem persists. I couldn't find anything 
special in directory "/tmp". But since I don't know what 
"template_cache_dir" should do I don't know what to expect from it...

 > Is it on a fast hard drive? You could try mounting a tmpfs filesystem
 > in there and compare results.

The Koha host resides in a virtual machine (run by Hyper-V, using 
Integrated Services). Unfortunately I have no direct access to the 
console there.

 > Also for debugging you should better use plack's tools instead:
 >
 > enable 'Debug', panels => [ qw(DBITrace Memory Timer) ];
 >
 > In plack.psgi and even the NTYProf panel. Maybe we need to improve the
 > docs for this.

I added this line to file "plack.psgi" and restarted Koha. Koha wasn't 
responding anymore but the file "plack-error.log" said:

  Error while loading /etc/koha/plack.psgi: Can't locate 
Plack/Middleware/Debug.pm in @INC (you may need to install the 
Plack::Middleware::Debug module) (@INC contains: 
/usr/share/koha/lib/installer /usr/share/koha/lib /etc/perl 
/usr/local/lib/x86_64-linux-gnu/perl/5.20.2 /usr/local/share/perl/5.20.2 
/usr/lib/x86_64-linux-gnu/perl5/5.20 /usr/share/perl5 
/usr/lib/x86_64-linux-gnu/perl/5.20 /usr/share/perl/5.20 
/usr/local/lib/site_perl .) at /etc/koha/plack.psgi line 29.

I tried to add "use Plack::Middleware::Debug;" to the file but it turned 
out this Perl module isn't part of the Koha installation, so I installed it:

# apt-get install libplack-middleware-debug-perl

Then I activated the following lines in file "plack.psgi".

use Plack::Middleware::Debug;
...
enable 'Debug', panels => [ qw(DBITrace Memory Timer) ];

Then I restarted Koha. This gave me no additional output in logfile 
"plack-error.log".

My time measurement still gives the following:

1. 12:45:14 START opac-user.pl / 1494420314.20786
2. 12:45:14 START opac-user.pl (right before function) / 1494420314.41777
* 4. 12:45:47 START function (in Output.pm) called by opac-user.pl
* 5. 12:45:47 END   function (in Output.pm) called by opac-user.pl
*    TIME  function: 0.00157809257507324
6. 12:45:47 END   opac-user.pl / 1494420347.53212
    TIME : 33.3242571353912

When everything is done the following lines appear in file "plack.log".

178.238.175.156 - - [10/May/2017:14:45:47 +0200] "POST 
/opac/opac-user.pl HTTP/1.1" 200 319007 
"http://bibliothek.phsh.ch/cgi-bin/koha/opac-main.pl?logout.x=1" 
"Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:53.0) Gecko/20100101 
Firefox/53.0"
178.238.175.156 - - [10/May/2017:14:45:48 +0200] "GET 
/opac/errors/404.pl HTTP/1.1" 404 205852 
"http://bibliothek.phsh.ch/cgi-bin/koha/opac-user.pl" "Mozilla/5.0 (X11; 
Ubuntu; Linux x86_64; rv:53.0) Gecko/20100101 Firefox/53.0"
178.238.175.156 - - [10/May/2017:14:45:48 +0200] "GET 
/opac/errors/404.pl HTTP/1.1" 404 205852 
"http://bibliothek.phsh.ch/cgi-bin/koha/opac-user.pl" "Mozilla/5.0 (X11; 
Ubuntu; Linux x86_64; rv:53.0) Gecko/20100101 Firefox/53.0"

Does this make some sense to you?

Best wishes: Michael (slowly going nuts...)
-- 
Geschäftsführer · Diplombibliothekar BBS, Informatiker eidg. Fachausweis
Admin Kuhn GmbH · Pappelstrasse 20 · 4123 Allschwil · Schweiz
T 0041 (0)61 261 55 61 · E mik at adminkuhn.ch · W www.adminkuhn.ch