[Koha] Slow Koha OPAC login process

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