Edit report at http://bugs.php.net/bug.php?id=52948&edit=1
ID: 52948 Updated by: cataphr...@php.net Reported by: gilles dot rayrat at continuent dot com Summary: Improper connection closing logic leads to TIME_WAIT sockets on server -Status: Open +Status: Feedback Type: Bug Package: MySQLi related Operating System: Any PHP Version: 5.2.14 Block user comment: N New Comment: I can't reproduce this. Are you using mysqlnd? With the mysql client (package for Ubuntu 10.4), I sometimes get a simultaneous shutdown (which means TIME_WAIT on both sides): (look only at the source, 192.168.1.102 is the client and 192.168.1.2 is the server; the varying destination is because of DNAT) 02:20:31.109223 IP (tos 0x8, ttl 64, id 30843, offset 0, flags [DF], proto TCP (6), length 57) 192.168.1.102.50375 > 79.168.249.157.3306: P 451:456(5) ack 5105 win 23584 <nop,nop,timestamp 549252121 211008142> 02:20:31.109535 IP (tos 0x8, ttl 64, id 30844, offset 0, flags [DF], proto TCP (6), length 52) 192.168.1.102.50375 > 79.168.249.157.3306: F, cksum 0xe3b8 (correct), 456:456(0) ack 5105 win 23584 <nop,nop,timestamp 549252121 211008142> 02:20:31.109766 IP (tos 0x0, ttl 128, id 7011, offset 0, flags [DF], proto TCP (6), length 52) 192.168.1.2.3306 > 192.168.1.1.50375: F, cksum 0xc83d (correct), 5105:5105(0) ack 456 win 64705 <nop,nop,timestamp 211008872 549252121> 02:20:31.110026 IP (tos 0x0, ttl 128, id 7012, offset 0, flags [DF], proto TCP (6), length 52) 192.168.1.2.3306 > 192.168.1.1.50375: ., cksum 0xc83c (correct), ack 457 win 64705 <nop,nop,timestamp 211008872 549252121> 02:20:31.112839 IP (tos 0x8, ttl 64, id 30845, offset 0, flags [DF], proto TCP (6), length 52) 192.168.1.102.50375 > 79.168.249.157.3306: ., cksum 0xe0dd (correct), ack 5106 win 23584 <nop,nop,timestamp 549252121 211008872> Other times I get the same I get with your example script, a client initiated shutdown, with TIME_WAIT only on the client): 02:24:51.798486 IP (tos 0x0, ttl 64, id 18397, offset 0, flags [DF], proto TCP (6), length 57) 192.168.1.102.55529 > 79.168.249.157.3306: P 70:75(5) ack 79 win 5840 <nop,nop,timestamp 549278188 211034639> 02:24:51.798790 IP (tos 0x0, ttl 64, id 18398, offset 0, flags [DF], proto TCP (6), length 52) 192.168.1.102.55529 > 79.168.249.157.3306: F, cksum 0x3dd4 (correct), 75:75(0) ack 79 win 5840 <nop,nop,timestamp 549278188 211034639> 02:24:51.800286 IP (tos 0x0, ttl 128, id 8297, offset 0, flags [DF], proto TCP (6), length 52) 192.168.1.2.3306 > 192.168.1.1.55529: ., cksum 0xdd38 (correct), ack 76 win 65086 <nop,nop,timestamp 211034940 549278188> 02:24:51.800583 IP (tos 0x0, ttl 128, id 8298, offset 0, flags [DF], proto TCP (6), length 52) 192.168.1.2.3306 > 192.168.1.1.55529: F, cksum 0xdd37 (correct), 79:79(0) ack 76 win 65086 <nop,nop,timestamp 211034940 549278188> 02:24:51.802275 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52) 192.168.1.102.55529 > 79.168.249.157.3306: ., cksum 0x3ca6 (correct), ack 80 win 5840 <nop,nop,timestamp 549278188 211034940> Looking at the source code for mysqlnd, it just calls the PHP stream closing function, which, on Linux, is just a call to close(). I'm by no means a socket expert, but from what I read, unless someone messed with the linger options, close() will send the FIN as soon as it's emptied the send buffer. I don't see how calling shutdown explicitly could possibly help. Previous Comments: ------------------------------------------------------------------------ [2010-09-30 09:03:39] gilles dot rayrat at continuent dot com php: No. Time Source Destination Protocol Info 1 0.000000 192.168.50.129 192.168.50.128 TCP 57338 > mysql [SYN] Seq=0 Win=5840 Len=0 MSS=1460 TSV=88257291 TSER=0 WS=5 2 0.000550 192.168.50.128 192.168.50.129 TCP mysql > 57338 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460 TSV=170478509 TSER=88257291 WS=5 3 0.000574 192.168.50.129 192.168.50.128 TCP 57338 > mysql [ACK] Seq=1 Ack=1 Win=5856 Len=0 TSV=88257291 TSER=170478509 4 0.001434 192.168.50.128 192.168.50.129 MySQL Server Greeting proto=10 version=5.1.26-rc-log 5 0.001960 192.168.50.129 192.168.50.128 TCP 57338 > mysql [ACK] Seq=1 Ack=64 Win=5856 Len=0 TSV=88257292 TSER=170478510 6 0.005680 192.168.50.129 192.168.50.128 MySQL Login Request user=tungsten db=test 7 0.006010 192.168.50.128 192.168.50.129 TCP mysql > 57338 [ACK] Seq=64 Ack=72 Win=5792 Len=0 TSV=170478511 TSER=88257293 8 0.006073 192.168.50.128 192.168.50.129 MySQL Response OK 9 0.006383 192.168.50.129 192.168.50.128 MySQL Request Quit 10 0.006618 192.168.50.128 192.168.50.129 TCP mysql > 57338 [FIN, ACK] Seq=75 Ack=77 Win=5792 Len=0 TSV=170478511 TSER=88257293 11 0.006672 192.168.50.129 192.168.50.128 TCP 57338 > mysql [FIN, ACK] Seq=77 Ack=76 Win=5856 Len=0 TSV=88257293 TSER=170478511 12 0.007198 192.168.50.128 192.168.50.129 TCP mysql > 57338 [ACK] Seq=76 Ack=78 Win=5792 Len=0 TSV=170478511 TSER=88257293 mysql CLI: No. Time Source Destination Protocol Info 1 0.000000 192.168.50.129 192.168.50.128 TCP 57339 > mysql [SYN] Seq=0 Win=5840 Len=0 MSS=1460 TSV=88268477 TSER=0 WS=5 2 0.000453 192.168.50.128 192.168.50.129 TCP mysql > 57339 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460 TSV=170489695 TSER=88268477 WS=5 3 0.000671 192.168.50.129 192.168.50.128 TCP 57339 > mysql [ACK] Seq=1 Ack=1 Win=5856 Len=0 TSV=88268477 TSER=170489695 4 0.001337 192.168.50.128 192.168.50.129 MySQL Server Greeting proto=10 version=5.1.26-rc-log 5 0.001504 192.168.50.129 192.168.50.128 TCP 57339 > mysql [ACK] Seq=1 Ack=64 Win=5856 Len=0 TSV=88268477 TSER=170489695 6 0.001685 192.168.50.129 192.168.50.128 MySQL Login Request user=tungsten db=test 7 0.001872 192.168.50.128 192.168.50.129 TCP mysql > 57339 [ACK] Seq=64 Ack=72 Win=5792 Len=0 TSV=170489695 TSER=88268477 8 0.001984 192.168.50.128 192.168.50.129 MySQL Response OK 9 0.003621 192.168.50.129 192.168.50.128 MySQL Request Query 10 0.004348 192.168.50.128 192.168.50.129 MySQL Response 11 0.004764 192.168.50.129 192.168.50.128 MySQL Request Query 12 0.005434 192.168.50.128 192.168.50.129 MySQL Response 13 0.005698 192.168.50.129 192.168.50.128 MySQL Request Show Fields 14 0.005941 192.168.50.128 192.168.50.129 MySQL Response 15 0.006104 192.168.50.129 192.168.50.128 MySQL Request Show Fields 16 0.006336 192.168.50.128 192.168.50.129 MySQL Response 17 0.006438 192.168.50.129 192.168.50.128 MySQL Request Show Fields 18 0.006650 192.168.50.128 192.168.50.129 MySQL Response 19 0.006760 192.168.50.129 192.168.50.128 MySQL Request Show Fields 20 0.006975 192.168.50.128 192.168.50.129 MySQL Response 21 0.007077 192.168.50.129 192.168.50.128 MySQL Request Show Fields 22 0.007325 192.168.50.128 192.168.50.129 MySQL Response 23 0.007884 192.168.50.129 192.168.50.128 MySQL Request Show Fields 24 0.008327 192.168.50.128 192.168.50.129 MySQL Response 25 0.008498 192.168.50.129 192.168.50.128 MySQL Request Show Fields 26 0.008752 192.168.50.128 192.168.50.129 MySQL Response 27 0.008859 192.168.50.129 192.168.50.128 MySQL Request Show Fields 28 0.009156 192.168.50.128 192.168.50.129 MySQL Response 29 0.009269 192.168.50.129 192.168.50.128 MySQL Request Show Fields 30 0.009541 192.168.50.128 192.168.50.129 MySQL Response 31 0.009662 192.168.50.129 192.168.50.128 MySQL Request Show Fields 32 0.009892 192.168.50.128 192.168.50.129 MySQL Response 33 0.010019 192.168.50.129 192.168.50.128 MySQL Request Show Fields 34 0.010301 192.168.50.128 192.168.50.129 MySQL Response 35 0.010411 192.168.50.129 192.168.50.128 MySQL Request Show Fields 36 0.010637 192.168.50.128 192.168.50.129 MySQL Response 37 0.010762 192.168.50.129 192.168.50.128 MySQL Request Show Fields 38 0.011006 192.168.50.128 192.168.50.129 MySQL Response 39 0.011109 192.168.50.129 192.168.50.128 MySQL Request Show Fields 40 0.011342 192.168.50.128 192.168.50.129 MySQL Response 41 0.011470 192.168.50.129 192.168.50.128 MySQL Request Query 42 0.011854 192.168.50.128 192.168.50.129 MySQL Response 43 0.051473 192.168.50.129 192.168.50.128 TCP 57339 > mysql [ACK] Seq=312 Ack=1521 Win=8000 Len=0 TSV=88268490 TSER=170489698 44 1.131630 192.168.50.129 192.168.50.128 MySQL Request Quit 45 1.131800 192.168.50.129 192.168.50.128 TCP 57339 > mysql [FIN, ACK] Seq=317 Ack=1521 Win=8000 Len=0 TSV=88268760 TSER=170489698 46 1.132174 192.168.50.128 192.168.50.129 TCP mysql > 57339 [FIN, ACK] Seq=1521 Ack=318 Win=5792 Len=0 TSV=170489978 TSER=88268760 47 1.132274 192.168.50.129 192.168.50.128 TCP 57339 > mysql [ACK] Seq=318 Ack=1522 Win=8000 Len=0 TSV=88268760 TSER=170489978 ------------------------------------------------------------------------ [2010-09-30 08:45:50] gilles dot rayrat at continuent dot com Thanks for your answer. Yes, the webserver should get the time_wait connections, since you can have several web servers but generally only one database server Furthermore, other mysql client (perl, CLI) will properly let the time_wait connection on the client side After some more testing, it actually appears that the behavior is somehow unpredictable (or I didn't get the logic). I sometimes got time_wait on the client, sometimes on the server - the following shows the case where it appears on the server. These tests are comparing regular mysql CLI client with a simple php script. Host u1 is the client (or webapp) Host u2 is the mysql server Mysql command line is: mysql -hu2 -utungsten -psecret -P3306 test Php script is: <?php # Simple script to demonstrate the TIME_WAIT issue # Connects to the database, nothing more $host = "u2"; # Host where the Tungsten Connector is running $port = 3306; # Using the Tungsten Connector port $username = "tungsten"; $password = "secret"; $dbname = "test"; echo "Connecting to $host $username $password $dbname $port\n"; # Make the connection $connection = mysqli_connect($host, $username, $password, $dbname, $port); $connection->close(); ?> Command to check for time_wait: netstat -nat| grep 3306| grep TIME_WAIT Will attach both dumps taken with wireshark ------------------------------------------------------------------------ [2010-09-30 05:14:41] cataphr...@php.net I'm sorry, I didn't get this. If I understand correctly, you would prefer the web server to be in a TIME_WAIT, rather than the database server, and for that it would have to send the first FIN packet. But why would you prefer the web server to be in a TIME_WAIT state? The front-end side typically needs to handle many more connections. Additionally, it would be nice if you provided an example script and its ouput (in this case, a tcpdump). ------------------------------------------------------------------------ [2010-09-29 08:36:08] gilles dot rayrat at continuent dot com Description: ------------ Similarly to connector/j bug reported here: http://bugs.mysql.com/bug.php? id=56979, there is a problem with mysql disconnection logic where the TCP connection TIME_WAIT state is found on the server rather than on the client. With multiple clients and multiple connection, the MySQL server can run out of file descriptors quickly. The disconnect method should first set EOF to its input, then send the QUIT command, then set its output to EOF, then close the socket Note: I guess the same bug appears in MySQL-non-i as well ------------------------------------------------------------------------ -- Edit this bug report at http://bugs.php.net/bug.php?id=52948&edit=1