Edit report at http://bugs.php.net/bug.php?id=52948&edit=1
ID: 52948
User updated by: gilles dot rayrat at continuent dot com
Reported by: gilles dot rayrat at continuent dot com
Summary: Improper connection closing logic leads to TIME_WAIT
sockets on server
-Status: Feedback
+Status: Open
Type: Bug
Package: MySQLi related
Operating System: Any
PHP Version: 5.2.14
Block user comment: N
New Comment:
I'm not sure what I'm using, I am not a php user. I run ubuntu 9.10 and
got the
package "php5-mysql". If you need further info, please advise on how to
collect
it.
I also encountered the case of double time_wait, I guess that the
behavior is
not fully predictable, and depends on whom between server and client
starts the
connection closing first.
Using, on client, shutdown(sock, SHUT_RD) before sending the quit
command, then
running shutdown(sock, SHUT_WR) will give more predictable (and, at
least to me,
appropriate) results
Previous Comments:
------------------------------------------------------------------------
[2010-10-01 03:10:15] [email protected]
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.
------------------------------------------------------------------------
[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
------------------------------------------------------------------------
The remainder of the comments for this report are too long. To view
the rest of the comments, please view the bug report online at
http://bugs.php.net/bug.php?id=52948
--
Edit this bug report at http://bugs.php.net/bug.php?id=52948&edit=1
