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. Do you have template_cache_dir set? Is it on a fast hard drive? You could try mounting a tmpfs filesystem in there and compare results. 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. El mié., 10 de may. de 2017 6:25 AM, Michael Kuhn <mik@adminkuhn.ch> escribió:
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@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
-- Tomás Cohen Arazi Theke Solutions (https://theke.io <http://theke.io/>) ✆ +54 9351 3513384 GPG: B2F3C15F