Re: [Koha] Slow Koha OPAC login process

18 Apr 2017

      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:

write(12, "Status: 200 OK\r\nSet-Cookie: CGIS"..., 8192) = 8192
write(12, "dsearch -->\n \n\n <div class=\"row-"..., 8192) = 8192
write(12, "GS_DELETED = _(\"Hinzugef\303\274gte Ta"..., 8192) = 8192
rt_sigprocmask(SIG_BLOCK, [STKFLT], [], 8) = 0
rt_sigaction(SIGSTKFLT, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_7], [], 8) = 0
rt_sigaction(SIGRT_7, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_11], [], 8) = 0
rt_sigaction(SIGRT_11, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [TERM], [], 8) = 0
rt_sigaction(SIGTERM, {0x7fd5bd4d4b40, [], SA_RESTORER, 0x7fd5bcd11890}, 
{0x7fd5bd4d4b40, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_4], [], 8) = 0
rt_sigaction(SIGRT_4, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [XCPU], [], 8) = 0
rt_sigaction(SIGXCPU, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [KILL], [], 8) = 0
rt_sigaction(SIGKILL, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
0x7ffc3dff2ad0, 8) = -1 EINVAL (Invalid argument)
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_15], [], 8) = 0
rt_sigaction(SIGRT_15, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [URG], [], 8) = 0
rt_sigaction(SIGURG, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_22], [], 8) = 0
rt_sigaction(SIGRT_22, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_17], [], 8) = 0
rt_sigaction(SIGRT_17, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [IO], [], 8)  = 0
rt_sigaction(SIGIO, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [TTIN], [], 8) = 0
rt_sigaction(SIGTTIN, {0x7fd5bd4d4b40, [], SA_RESTORER, 0x7fd5bcd11890}, 
{0x7fd5bd4d4b40, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_14], [], 8) = 0
rt_sigaction(SIGRT_14, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [PIPE], [], 8) = 0
rt_sigaction(SIGPIPE, {SIG_IGN, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_IGN, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [CONT], [], 8) = 0
rt_sigaction(SIGCONT, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_26], [], 8) = 0
rt_sigaction(SIGRT_26, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [FPE], [], 8) = 0
rt_sigaction(SIGFPE, {SIG_IGN, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_IGN, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_6], [], 8) = 0
rt_sigaction(SIGRT_6, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_24], [], 8) = 0
rt_sigaction(SIGRT_24, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [QUIT], [], 8) = 0
rt_sigaction(SIGQUIT, {0x7fd5bd4d4b40, [], SA_RESTORER, 0x7fd5bcd11890}, 
{0x7fd5bd4d4b40, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_13], [], 8) = 0
rt_sigaction(SIGRT_13, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [INT], [], 8) = 0
rt_sigaction(SIGINT, {0x7fd5bd4d4b40, [], SA_RESTORER, 0x7fd5bcd11890}, 
{0x7fd5bd4d4b40, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_8], [], 8) = 0
rt_sigaction(SIGRT_8, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_32], [], 8) = 0
rt_sigaction(SIGRT_32, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_27], [], 8) = 0
rt_sigaction(SIGRT_27, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_16], [], 8) = 0
rt_sigaction(SIGRT_16, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_29], [], 8) = 0
rt_sigaction(SIGRT_29, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_30], [], 8) = 0
rt_sigaction(SIGRT_30, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [PROF], [], 8) = 0
rt_sigaction(SIGPROF, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RTMIN], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [TRAP], [], 8) = 0
rt_sigaction(SIGTRAP, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_5], [], 8) = 0
rt_sigaction(SIGRT_5, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [PWR], [], 8) = 0
rt_sigaction(SIGPWR, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_23], [], 8) = 0
rt_sigaction(SIGRT_23, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_3], [], 8) = 0
rt_sigaction(SIGRT_3, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [STOP], [], 8) = 0
rt_sigaction(SIGSTOP, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
0x7ffc3dff2ad0, 8) = -1 EINVAL (Invalid argument)
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [SYS], [], 8) = 0
rt_sigaction(SIGSYS, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [WINCH], [], 8) = 0
rt_sigaction(SIGWINCH, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_12], [], 8) = 0
rt_sigaction(SIGRT_12, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [USR2], [], 8) = 0
rt_sigaction(SIGUSR2, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_20], [], 8) = 0
rt_sigaction(SIGRT_20, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_21], [], 8) = 0
rt_sigaction(SIGRT_21, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [XFSZ], [], 8) = 0
rt_sigaction(SIGXFSZ, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_28], [], 8) = 0
rt_sigaction(SIGRT_28, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [ABRT], [], 8) = 0
rt_sigaction(SIGABRT, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_18], [], 8) = 0
rt_sigaction(SIGRT_18, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [VTALRM], [], 8) = 0
rt_sigaction(SIGVTALRM, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [IO], [], 8)  = 0
rt_sigaction(SIGIO, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [TTOU], [], 8) = 0
rt_sigaction(SIGTTOU, {0x7fd5bd4d4b40, [], SA_RESTORER, 0x7fd5bcd11890}, 
{0x7fd5bd4d4b40, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [ILL], [], 8) = 0
rt_sigaction(SIGILL, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [ABRT], [], 8) = 0
rt_sigaction(SIGABRT, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_19], [], 8) = 0
rt_sigaction(SIGRT_19, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_1], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_31], [], 8) = 0
rt_sigaction(SIGRT_31, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_25], [], 8) = 0
rt_sigaction(SIGRT_25, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [BUS], [], 8) = 0
rt_sigaction(SIGBUS, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_10], [], 8) = 0
rt_sigaction(SIGRT_10, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [USR1], [], 8) = 0
rt_sigaction(SIGUSR1, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [TSTP], [], 8) = 0
rt_sigaction(SIGTSTP, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_9], [], 8) = 0
rt_sigaction(SIGRT_9, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [HUP], [], 8) = 0
rt_sigaction(SIGHUP, {0x7fd5bd4d4b40, [], SA_RESTORER, 0x7fd5bcd11890}, 
{0x7fd5bd4d4b40, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [ALRM], [], 8) = 0
rt_sigaction(SIGALRM, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [SYS], [], 8) = 0
rt_sigaction(SIGSYS, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [SEGV], [], 8) = 0
rt_sigaction(SIGSEGV, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [RT_2], [], 8) = 0
rt_sigaction(SIGRT_2, {SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 
{SIG_DFL, [], SA_RESTORER, 0x7fd5bcd11890}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
chdir("/")                              = 0
prctl(PR_SET_NAME, 0x1d79ae0, 0, 0, 0)  = 0
write(12, "argets\" : [ \"title-string\" ] }\n "..., 1696) = 1696
lseek(12, 0, SEEK_SET)                  = 0
lseek(12, 0, SEEK_CUR)                  = 0
ioctl(12, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or 
TCGETS, 0x7ffc3dff2bd0) = -1 ENOTTY (Inappropriate ioctl for device)
lseek(12, 0, SEEK_CUR)                  = 0
fstat(12, {st_mode=S_IFREG|0600, st_size=26272, ...}) = 0
fcntl(12, F_SETFD, FD_CLOEXEC)          = 0
fstat(12, {st_mode=S_IFREG|0600, st_size=26272, ...}) = 0
read(12, "Status: 200 OK\r\nSet-Cookie: CGIS"..., 8192) = 8192
read(12, "dsearch -->\n \n\n <div class=\"row-"..., 8192) = 8192
read(12, "GS_DELETED = _(\"Hinzugef\303\274gte Ta"..., 8192) = 8192
read(12, "argets\" : [ \"title-string\" ] }\n "..., 8192) = 1696
read(12, "", 8192)                      = 0
close(12)                               = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1892, ...}) = 0
write(4, "178.238.175.156 - - [18/Apr/2017"..., 238) = 238
write(9, "HTTP/1.1 200 OK\r\nCache-Control: "..., 418) = 418
write(9, "\n\n\n\n\n\n<!DOCTYPE html>\n<!-- TEMPL"..., 25902) = 25902
select(16, [9], NULL, NULL, {1, 0})     = 0 (Timeout)
close(9)                                = 0
kill(26131, SIG_0)                      = 0
write(8, "62503 waiting\n", 14)         = 14
getsockopt(6, SOL_SOCKET, SO_TYPE, [1], [4]) = 0
accept(6,

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 · E mik@adminkuhn.ch · W www.adminkuhn.ch

Re: [Koha] Slow Koha OPAC login process

Michael Kuhn