[Koha] Slow Koha OPAC login process

[Michael Kuhn]

Hi

Yesterday Mark Alexander wrote:

> Excerpts from Michael Kuhn's message of 2017-05-09 19:57:51 +0200:
>> With my poor Perl knowledge I have now measured the execution time of
>> the various parts of script "opac-user.pl". As I found out everything is
>> always very fast (using less than 1 second execution time) except the
>> very last function in this script which looks as follows:
>>
>> output_with_http_headers $cgi, $cookie, $template->output, $content_type;
>
> I am not familiar with this code, but I took a quick look at it just
> now.  If I were trying to debug this problem, I would measure the
> execution time of the last statement in output_with_http_headers:
>
>     print $query->header($options), $data;
>
> If I understand correctly, this print is going to send a big blob of
> HTML (preceded by a header) via Apache to the client.  If Apache is
> timing out for some reason, perhaps that would cause a big delay in
> this print statement.

It doesn't seem to be the function itself that takes the time.

I have now changed the scripts "output-user.pl" and "Output.pm" as 
follows so they will give me the time at certain moments:

1. Print time at the very beginning of script "output-user.pl"

2. Print time just before calling function 
"output_html_with_http_headers" in script "output-user.pl"

3. Print time at the very beginning of script "Output.pm"

4. Print time at the very beginning in function 
"output_html_with_http_headers" in script "Output.pm"

5. Print time at the end in function "output_html_with_http_headers" in 
script "Output.pm"

6. Print time after calling function "output_html_with_http_headers" in 
script "output-user.pl"

I would have expected the output in this order, but in fact I get the 
following sequence:

3. 09:18:44 START (Output.pm called by plack.psgi)
1. 09:18:44 START opac-user.pl / 1494407924.86717
2. 09:18:45 START opac-user.pl (right before function) / 1494407925.45211
* 4. 09:19:17 START function (in Output.pm) called by opac-user.pl
* 5. 09:19:17 END   function (in Output.pm) called by opac-user.pl
*    TIME  function: 0.0027921199798584
6. 09:19:17 END   opac-user.pl / 1494407957.18462
    TIME : 32.3174500465393

If I disable Plack I get the following sequence (no output for 3.):

1. 09:20:48 START opac-user.pl / 1494408048.50046
2. 09:20:48 START opac-user.pl (right before function) / 1494408048.74332
* 4. 09:21:20 START function (in Output.pm) called by opac-user.pl
* 5. 09:21:20 END   function (in Output.pm) called by opac-user.pl
*    TIME  function: 0.00142717361450195
6. 09:21:20 END   opac-user.pl / 1494408080.4559
    TIME : 31.9554369449615

However everything works very fast and fine in script "opac-user.pl" 
until the function "output_html_with_http_headers" is called. Then it 
takes about 32 seconds until the function 
"output_html_with_http_headers" actually starts its work, the function 
itself then works very fast again.

Does anybody have an idea what could cause this very annoying delay 
before the function is actually starting its work?

I'm not sure if there is a connection but when I restart Koha using 
"service koha-common" it is sometimes very fast and sometimes it takes 
about 30 seconds too.

Best wishes: Michael
-- 
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