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 <m...@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 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
_______________________________________________
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
