system call

Shell Programming and Scripting
1

Trying to figure out a load issue with a webserver. I have traced a php script and noticed the following

connect(4, {sa_family=AF_INET, sin_port=htons(3306), sin_addr=inet_addr("XX.XX.XX.XX")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.000035>
poll([{fd=4, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 2000) = 1 ([{fd=4, revents=POLLOUT}]) <0.000120>
getsockopt(4, SOL_SOCKET, SO_ERROR, [8589934592], [4]) = 0 <0.000006>
fcntl(4, F_SETFL, O_RDWR)               = 0 <0.000005>
setsockopt(4, SOL_TCP, TCP_NODELAY, [1], 4) = 0 <0.000006>
poll([{fd=4, events=POLLIN|POLLERR|POLLHUP}], 1, 1471228928) = 1 ([{fd=4, revents=POLLIN}]) <1.122287>

Looks like a connection to db server in same LAN taking time.

It looks like poll takes more than 1 sec. Is this a network issue?

-Raj

2

poll is waiting on the socket to get something sent to it. If there are a lot of waits, there can be a network latency issue. Usually I suspect the code as the culprit first, then look at the network.

And yes, if you routinely have 1+ second waits on receiving data, then something somewhere is way wrong.

3

I see nothing wrong with the trace (copied below with an other formatting):

           connect(4, {sa_family=AF_INET, sin_port=htons(3306), sin_addr=inet_addr("XX.XX.XX.XX")}, 16) = -1 EINPROGRESS 
           (Operation now in progress) 
<0.000035> poll([{fd=4, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 2000) = 1 ([{fd=4, revents=POLLOUT}]) 
<0.000120> getsockopt(4, SOL_SOCKET, SO_ERROR, [8589934592], [4]) = 0 
<0.000006> fcntl(4, F_SETFL, O_RDWR) = 0 
<0.000005> setsockopt(4, SOL_TCP, TCP_NODELAY, [1], 4) = 0 
<0.000006> poll([{fd=4, events=POLLIN|POLLERR|POLLHUP}], 1, 1471228928) = 1 ([{fd=4, revents=POLLIN}]) 
<1.122287>

First, the client tries to connect to the server using (probably) non blocking socket. Upon receiving EINPROGRESS, it then polls() on the socket for connection completion with a max timeout of 2s. Very soon, the connection completes. The clients set then various options on the socket, and calls again poll() with a timeout of 1471228.928s, which completes after 1.12s with event input data received. This is fine.

Question: Is the timeout of 1471228.928s really intended?

4

No, its not intented. in php mysql client timeout set to 4 secs only. So scripts should not wait more than 4 secs. i can see large number of delayed poll() calls, few are above 10 secs. Do you think its a bug in mysql client?

-Raj

5

I do not know.

If the mysql interface you're using is well-known, chance is that either you made a mistake when using the interface or the interface has a (probably known) bug. If you can prove that everything you're doing everything right at your layer, but not at the layer below, then pass the ticket "down" :wink:

/Lew

6

Thanks. Issue suddenly started happening after we moved to a new mysql server. So it must not be client issue.

-Raj