[Koha] Slow Koha OPAC login process

[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 <mik at 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 at lists.katipo.co.nz
> https://lists.katipo.co.nz/mailman/listinfo/koha
>