My Apache server takes long time to process request. I attached strace to it and can see the two following delays:
1) Very critical (143 seconds to process)
1335 0.000037 write(16, "\235\0\0\0\3INSERT INTO `br_anonymous_user_tokens` (`dtExpires`, `nmToken`, `dtCreated`) VALUES ('2014-08-25', '46e35dc39a41e836b806f48d21621b066ea182a9', '2014-06-25')", 161) = 161
1335 0.000111 read(16, "\t\0\0\1\0\1\374\262\n\2\0\0\0", 16384) = 13
1335 143.588134 gettimeofday({1403675497, 653337}, NULL) = 0
File descriptor #16 seems to be mysql socket:
line from strace
1335 0.000328 socket(PF_LOCAL, SOCK_STREAM, 0) = 16
And here
pidof mysqld
15393
lsof -p 15393
mysqld 15393 mysql 12u IPv4 26913133 0t0 TCP *:mysql (LISTEN)
So it seems that Apache is waiting for mysql to execute the query which was written to the socket on the previous line. Am I right? Does it mean that I then need to understand why it takes so long for MySQL to execute simple query?
2) Very long
1335 0.000040 poll([{fd=14, events=POLLIN}], 1, 5000) = 0 (Timeout)
1335 5.005295 gettimeofday({1403675502, 686212}, NULL) = 0
Here I tried to locate file descriptor #14 to find out where the timeout comes from. I used techniques described here, but none of them showed the descriptor in question. How can I find out where the timeout comes from?
The issue is resolved. I looked through the
PROCESSLIST
table ininformation_schema
MySQL database and found that some tables are locked with the stateWaiting for table level lock
. So then I searched and found that one reason for the lock can be mysqldump backups - and this is exactly what I had configured recently. But because the job was misconfigured, it ran every minute constantly locking MySQL. Now that backups are configured correctly, the server works fine.Yet the second question with
poll
remains unresolved.