[Koha] Slow Koha OPAC login process
Jonathan Druart
jonathan.druart at bugs.koha-community.org
Wed Apr 19 03:10:27 NZST 2017
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`
On Tue, 18 Apr 2017 at 11:31 Michael Kuhn <mik at adminkuhn.ch> wrote:
> 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>
> <+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 <+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
>
More information about the Koha
mailing list