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