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 m...@adminkuhn.ch · W www.adminkuhn.ch
_______________________________________________
Koha mailing list http://koha-community.org
Koha@lists.katipo.co.nz
https://lists.katipo.co.nz/mailman/listinfo/koha
