That's maybe just because it doesn't take the same amount of time with every attempt - sometimes it's 10 seconds, but (most of the time) it goes up to 40 seconds.

Am 18.04.2017 um 18:23 schrieb Jonathan Druart:
There are now 766 calls vs 1599 in your previous paste. I would have
expected more, less does not help :)
If it is the pl script execution that takes 30s, it should not come from
network latencies.

On Tue, 18 Apr 2017 at 13:09 Michael Kuhn <m...@adminkuhn.ch> wrote:

Hi Jonathan

I do not understand why %time is 0, should not be, especially if the
process takes 30s
Try to get the most complete output with a long query, then a complete
output with a normal query. Maybe we will see the differences between
both.
You should write a script not to have to retrieve the pid manually,
something using `ps aux | grep opac-user.pl | tr -s ' ' | cut -d' ' -f2`

Here's another attempt:

1. I made a login attempt.

2. As soon as I saw the query that was taking 99% of the CPU I executed
the following command in another terminal:

strace -c -p $(ps aux | grep -v grep | grep opac-user.pl | tr -s ' ' |
cut -d' ' -f2)

When the login finally succeeded I ended strace with CTRL+C. This is the
output:

Process 64958 attached
^CProcess 64958 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
   0.00    0.000000           0         5           read
   0.00    0.000000           0         8           write
   0.00    0.000000           0         2           close
   0.00    0.000000           0         1           stat
   0.00    0.000000           0         2           fstat
   0.00    0.000000           0         3           lseek
   0.00    0.000000           0         2           mmap
   0.00    0.000000           0       534           brk
   0.00    0.000000           0        66         2 rt_sigaction
   0.00    0.000000           0       136           rt_sigprocmask
   0.00    0.000000           0         1         1 ioctl
   0.00    0.000000           0         1           select
   0.00    0.000000           0         1           getsockopt
   0.00    0.000000           0         1           kill
   0.00    0.000000           0         1           fcntl
   0.00    0.000000           0         1           chdir
   0.00    0.000000           0         1           prctl
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                   766         3 total

Does this help?

 > Try to get the most complete output with a long query, then a complete
 > output with a normal query. Maybe we will see the differences between
 > both.

It is not possible to execute strace for a "normal" login attempt like
this because usually an attempt to log into the Koha OPAC is very quick,
so it is not possible to first click the "Login" button and then execute
strace in the terminal because meanwhile the login has already succeeded
and the above command will find no PID...

Is it maybe possible to measure the execution time within the sections
of the Perl script "opac-user.pl"?

Somehow the whole thing seems to me like some kind of network problem
(DNS? latency? timeout?) but I wouldn't know how to find out since I
don't really understand what "opac-user.pl" does.

Regards, Michael

_______________________________________________
Koha mailing list  http://koha-community.org
Koha@lists.katipo.co.nz
https://lists.katipo.co.nz/mailman/listinfo/koha

_______________________________________________
Koha mailing list  http://koha-community.org
Koha@lists.katipo.co.nz
https://lists.katipo.co.nz/mailman/listinfo/koha



--
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

Reply via email to