[Koha] Slow Koha OPAC login process

Michael Kuhn mik at adminkuhn.ch
Wed Apr 19 02:31:21 NZST 2017


Hi Jonathan

I made a new attempt to use strace which has a different and much 
shorter output:

1. I made a login attempt.

2. As soon as I saw the query was taking 99% of the CPU I picked the PID 
(here: 63895) from the output of "top" and executed the following command:

# strace -c -p 63895

When the login finally succeeded I ended strace with CTRL+C. The output 
then looked like the following (output can also be seen via 
http://adminkuhn.ch/download/strace.txt):

Process 63895 attached
^CProcess 63895 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
   0.00    0.000000           0       146           read
   0.00    0.000000           0       137           write
   0.00    0.000000           0         8           open
   0.00    0.000000           0        13           close
   0.00    0.000000           0        54        22 stat
   0.00    0.000000           0        19           fstat
   0.00    0.000000           0         5           lstat
   0.00    0.000000           0       123           poll
   0.00    0.000000           0        16         2 lseek
   0.00    0.000000           0       404           brk
   0.00    0.000000           0       202         6 rt_sigaction
   0.00    0.000000           0       416           rt_sigprocmask
   0.00    0.000000           0        12        12 ioctl
   0.00    0.000000           0         2           select
   0.00    0.000000           0         4           alarm
   0.00    0.000000           0         1           accept
   0.00    0.000000           0         2           getpeername
   0.00    0.000000           0         2           getsockopt
   0.00    0.000000           0         2           kill
   0.00    0.000000           0        11           fcntl
   0.00    0.000000           0         4           getdents
   0.00    0.000000           0         1           getcwd
   0.00    0.000000           0         3           chdir
   0.00    0.000000           0         1           unlink
   0.00    0.000000           0         2           geteuid
   0.00    0.000000           0         1           getegid
   0.00    0.000000           0         2           getgroups
   0.00    0.000000           0         4           prctl
   0.00    0.000000           0         2           openat
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                  1599        42 total

I wonder if this output is helpful?

Best wishes: Michael



Am 18.04.2017 um 16:02 schrieb Jonathan Druart:
> Use `strace -c -p PID` and paste the whole output please (hastebin or
> similar)
>
>
> On Tue, 18 Apr 2017 at 10:23 Michael Kuhn <mik at adminkuhn.ch> wrote:
>
>> Hi Marc and Jonatahn
>>
>> Marc wrote:
>>
>>> What version of Koha is it?
>>
>> We're running a new host with Debian GNU/Linux 8 and Koha 16.11.04.
>>
>>> Do you have errors or messages  in the log files?
>>> You can monitor them using tail. At first place I would have a look at
>>> opac-error.log and plack-error.log,
>>> something like: tail -f opac-error.log
>>
>> No, they are no errors or messages. As soon as the login attempt in the
>> Koha OPAC is made the, the following process taking 99% of the CPU can
>> be seen with "top" or "ps -ef":
>>
>> phsh-ko+ 62293 26131 30 14:39 ?        00:00:22
>> /usr/share/koha/opac/cgi-bin/opac/opac-user.pl
>>
>> When the login finally succeeds (after maybe 30 seconds) the following
>> is written in the file "plack.log":
>>
>> 178.238.175.156 - - [18/Apr/2017:14:40:28 +0200] "POST
>> /opac/opac-user.pl HTTP/1.1" 200 26320
>> "http://bibliothek.phsh.ch/cgi-bin/koha/opac-main.pl?logout.x=1"
>> "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:52.0) Gecko/20100101
>> Firefox/52.0"
>>
>> But nothing is written to the file "opac-error.log".
>>
>> Jonathan wrote:
>>
>>  > In production I am not aware of something you could do (well there is
>>  > strace if you are patient and quick :D)
>>  > In test you could use a code profiler or tell mysql to log slow
>>  > queries.
>>  > But the code profiler will be hazardous if it does not happens 100%
>>  > of the time and htop would have told you if mysql was the culprit.
>>
>> I activated the Mysql slow query log during runtime, using the following
>> commands:
>>
>> mysql> set global log_slow_queries = 1;
>> mysql> set global slow_query_log_file = '/tmp/slow.txt';
>>
>> Then I made another login attempt in the Koha OPAC. The file
>> "/tmp/slow.txt" is created but it doesn't list any slow query, so I
>> think the problem is not in the query itself:
>>
>> # more /tmp/slow.txt
>> /usr/sbin/mysqld, Version: 5.5.54-0+deb8u1 ((Debian)). started with:
>> Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
>> Time                 Id Command    Argument
>>
>> Then I made some attempt to use strace, but I'm not sure how to really
>> use it and especially how to interpret the output... So what i've tried is:
>>
>> 1. I made a login attempt
>>
>> 2. As soon as I saw the query was taking 99% of the CPU i picked the PID
>> (here: 62503) from the output of "top" and executed the following command:
>>
>> # strace -p 62503
>>
>> The output then looked like the folloing (full output at the end of this
>> email):
>>
>> Process 62503 attached
>>
>> followed by many many lines like the following:
>>
>> brk(0xb63b000)                          = 0xb63b000
>> brk(0xb65c000)                          = 0xb65c000
>> brk(0xb67d000)                          = 0xb67d000
>>
>> Then after about 30 seconds it says:
>> [SKIP]
>>
>> At this point the login attempt finally succeeds. Actually I have no
>> idea what this means - can you please help?
>>
>> 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 <+41%2061%20261%2055%2061> · E mik at adminkuhn.ch ·
>> W www.adminkuhn.ch
>> _______________________________________________
>> Koha mailing list  http://koha-community.org
>> Koha at lists.katipo.co.nz
>> https://lists.katipo.co.nz/mailman/listinfo/koha
>>
> _______________________________________________
> Koha mailing list  http://koha-community.org
> Koha at 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 mik at adminkuhn.ch · W www.adminkuhn.ch


More information about the Koha mailing list