Take the 2-minute tour ×
Server Fault is a question and answer site for system and network administrators. It's 100% free, no registration required.

We keep getting errors like this on our PHP sites.

Can't connect to MySQL server on '192.168.100.85' (4)

web is the web server 192.168.1.116
mysql is the mysql server 192.168.100.85

So I built a script on the web server to make 10,000 mysql connections in a row and time them. It will "sometimes" produce the error. Most times everything runs fine and there is an average time of 5-10 ms for the call to mysql_connect

Some serious Googling showed that the (4) error is due to the connection being cut off by the timeout.

web# grep mysql.connect_timeout /etc/php.ini
mysql.connect_timeout = 1

So I modified the timeout in the script to 30 to see if it would work. The connection errors went away, but occasionally the connection would take 5 seconds.

After more Googling and some tcpdump I found that occasionally when the MySQL server is doing its reverse lookup of the IP the DNS server would fail to respond. So after 5 seconds it would give up and allow the connection.

I have since added skip-name-resolve to the server. But this did not solve the problem.

Now my test would show slow connections taking 3-4.5 seconds instead of the set 5 with the DNS issue.

So I ran my tests again with tcpdump running on both ends.

web# tcpdump -n -s 65535 -w web3-$(date +"%F_%H-%M-%S").pcap host 192.168.100.85 and port 3306
mysql# tcpdump -n -s 65535 -w master1-$(date +"%F_%H-%M-%S").pcap host 192.168.1.116 and port 3306

Here is the packets from the relevant slow connection.

Packets from web:

No.     Time                       Source                Destination           Protocol Info
13312 2010-10-13 10:01:01.201965 192.168.1.116         192.168.100.85        TCP      41560 > mysql [SYN] Seq=0 Win=5840 Len=0 MSS=1460 TSV=904829062 TSER=0 WS=2
13316 2010-10-13 10:01:04.201577 192.168.1.116         192.168.100.85        TCP      41560 > mysql [SYN] Seq=0 Win=5840 Len=0 MSS=1460 TSV=904832062 TSER=0 WS=2
13317 2010-10-13 10:01:04.204837 192.168.100.85        192.168.1.116         TCP      mysql > 41560 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1380 TSV=562240314 TSER=904832062 WS=7
13318 2010-10-13 10:01:04.204853 192.168.1.116         192.168.100.85        TCP      41560 > mysql [ACK] Seq=1 Ack=1 Win=5840 Len=0 TSV=904832065 TSER=562240314
13319 2010-10-13 10:01:04.205886 192.168.100.85        192.168.1.116         MySQL    Server Greeting proto=10 version=5.0.77-log
13320 2010-10-13 10:01:04.205899 192.168.1.116         192.168.100.85        TCP      41560 > mysql [ACK] Seq=1 Ack=61 Win=5840 Len=0 TSV=904832066 TSER=562240316
13321 2010-10-13 10:01:04.205959 192.168.1.116         192.168.100.85        MySQL    Login Request userexample
13322 2010-10-13 10:01:04.206800 192.168.100.85        192.168.1.116         TCP      mysql > 41560 [ACK] Seq=61 Ack=71 Win=5888 Len=0 TSV=562240317 TSER=904832066
13323 2010-10-13 10:01:04.206874 192.168.100.85        192.168.1.116         MySQL    Response OK
13324 2010-10-13 10:01:04.208823 192.168.1.116         192.168.100.85        MySQL    Request Quit
13325 2010-10-13 10:01:04.208839 192.168.1.116         192.168.100.85        TCP      41560 > mysql [FIN, ACK] Seq=76 Ack=72 Win=5840 Len=0 TSV=904832069 TSER=562240317
13326 2010-10-13 10:01:04.210422 192.168.100.85        192.168.1.116         TCP      mysql > 41560 [FIN, ACK] Seq=72 Ack=76 Win=5888 Len=0 TSV=562240320 TSER=904832069
13327 2010-10-13 10:01:04.210437 192.168.1.116         192.168.100.85        TCP      41560 > mysql [ACK] Seq=77 Ack=73 Win=5840 Len=0 TSV=904832071 TSER=562240320
13328 2010-10-13 10:01:04.210567 192.168.100.85        192.168.1.116         TCP      mysql > 41560 [ACK] Seq=73 Ack=77 Win=5888 Len=0 TSV=562240320 TSER=904832069

Packets from mysql:

No.     Time                       Source                Destination           Protocol Info
13315 2010-10-13 10:01:04.204817 192.168.1.116         192.168.100.85        TCP      41560 > mysql [SYN] Seq=0 Win=5840 Len=0 MSS=1380 TSV=904832062 TSER=0 WS=2
13316 2010-10-13 10:01:04.204836 192.168.100.85        192.168.1.116         TCP      mysql > 41560 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460 TSV=562240314 TSER=904832062 WS=7
13317 2010-10-13 10:01:04.206611 192.168.1.116         192.168.100.85        TCP      41560 > mysql [ACK] Seq=1 Ack=1 Win=5840 Len=0 TSV=904832065 TSER=562240314
13318 2010-10-13 10:01:04.206808 192.168.100.85        192.168.1.116         MySQL    Server Greeting proto=10 version=5.0.77-log
13319 2010-10-13 10:01:04.207658 192.168.1.116         192.168.100.85        TCP      41560 > mysql [ACK] Seq=1 Ack=61 Win=5840 Len=0 TSV=904832066 TSER=562240316
13320 2010-10-13 10:01:04.207815 192.168.1.116         192.168.100.85        MySQL    Login Request user=example
13321 2010-10-13 10:01:04.207872 192.168.100.85        192.168.1.116         TCP      mysql > 41560 [ACK] Seq=61 Ack=71 Win=5888 Len=0 TSV=562240317 TSER=904832066
13322 2010-10-13 10:01:04.207910 192.168.100.85        192.168.1.116         MySQL    Response OK
13323 2010-10-13 10:01:04.210817 192.168.1.116         192.168.100.85        MySQL    Request Quit
13324 2010-10-13 10:01:04.210849 192.168.100.85        192.168.1.116         TCP      mysql > 41560 [FIN, ACK] Seq=72 Ack=76 Win=5888 Len=0 TSV=562240320 TSER=904832069
13325 2010-10-13 10:01:04.211632 192.168.1.116         192.168.100.85        TCP      41560 > mysql [FIN, ACK] Seq=76 Ack=72 Win=5840 Len=0 TSV=904832069 TSER=562240317
13326 2010-10-13 10:01:04.211640 192.168.100.85        192.168.1.116         TCP      mysql > 41560 [ACK] Seq=73 Ack=77 Win=5888 Len=0 TSV=562240320 TSER=904832069
13327 2010-10-13 10:01:04.213243 192.168.1.116         192.168.100.85        TCP      41560 > mysql [ACK] Seq=77 Ack=73 Win=5840 Len=0 TSV=904832071 TSER=562240320

As you can see, web re-sent the initial ACK after 3 seconds of no response. But mysql never even saw that initial packet.

I also tried to run a ping flood to check for dropped packets. If you leave it running long enough you will get dropped packets.

web3# ping -f 192.168.100.85
PING 192.168.100.85 (192.168.100.85) 56(84) bytes of data.
....................................................................
--- 192.168.100.85 ping statistics ---
38253 packets transmitted, 38185 received, 0% packet loss, time 460851ms
rtt min/avg/max/mdev = 0.880/3.430/66.904/8.015 ms, pipe 7, ipg/ewma 12.047/1.378 ms

This issue is very intermittent but is happening all the time. I do understand that simply increasing our timeout would help greatly, but I'd rather have the connects always be fast and never have a 3-4 second delay in serving a page.

I contacted our hosting provider and they say its likely a result of the bad interaction between Nagle's Algorithm and Delayed ACK. http://www.stuartcheshire.org/papers/NagleDelayedAck/

It seems to me like packets are being dropped. Any ideas on a way I could better prove it to the hosting guys? Ping dropping 60 out of 38,000 packets does seem kind of minor. Is this something I should just live with?

Thank you for your time in looking into this!

share|improve this question

1 Answer 1

up vote 0 down vote accepted

I wouldn't try it with a ping flood, but I would set up a continous stream and let it run for, say, 2 minutes. That's a more valid test of network "loss" - sometimes ping -f can overrun particular pieces of equipment and give unreliable results.

share|improve this answer
    
Marking this as answer since its the only one. We ended up upgrading a piece of networking gear between the two servers and have had much better performance since. –  Slashterix Jun 19 '12 at 3:50

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.