现象
mysqlnd的超时时间设置为2s后,出现了一个诡异的现象。在php的error log中出现了一些错误信息。如下:
[20-Dec-2014 21:20:17] WARNING: [pool www] child 31401 said into stderr: "NOTICE: PHP message: PHP Warning: PDO::__construct(): MySQL server has gone away in ./abstract.class.php on line 26"
第26行代码如下:
<?php
$this->resource = new PDO(
$this->type.':'.implode(';', $dsn).';charset=gbk',
$this->dbconf['username'],
$this->dbconf['password'],
$this->dbconf['driver_options']
);
$this->resource->setAttribute(PDO::ATTR_ERRMODE, PDO::ERRMODE_EXCEPTION);
?>
猜测
看来是因为创建pdo对象时出错的。创建pdo对象时会建立数据库连接,估计在建立数据库连接时超时导致报gone away错误。
验证
tcpdump抓包
首先,还原现场。把线上的一台机器重新把mysqlnd的超时设置为2s。然后,通过tcpdump命令抓包。命令行如下:
#tcpdump -i eth0 -s 3000 port 3306 -w ~/sql.pcap
同时,通过tail -f 命令实时查看php error log 的信息。一旦发现上面的gone away的错误信息,就可以停止tcpdump抓包了。记录下错误日志中出错时的时间点。例如出错的时间点为 2014-12-20 13:21:24。
wireshark分析包
简单的包分析使用tcpdump还行,但是复杂的数据包分析还是wireshark专业。
首先,根据过滤条件,找到所有创建数据库连接的数据包。
用wireshark打开sql.pcap文件后,使用显示过滤器过滤数据包。过滤条件为 “tcp contains password”。如图:
为什么要以 password去过滤数据包呢?因为创建数据库连接的时候,会向服务器端发送一个数据包,数据包中包含password关键字。有兴趣的话,大家可以使用tcpdump看下创建数据库连接时数据包内容。
其次,根据错误时间缩小范围
根据过滤条件过滤后,你会发现创建数据库连接的数据包很多。这个时候,我们可以根据出现错误的时间大概定位需要排查的数据包的范围。我们记录了出错的时间为2014-12-20 13:21:24,mysqlnd的超时时间设置的为2s,那么有问题的数据包可能就再 2014-12-20 13:21:22。这一秒的数据包就少很多了。
最后,使用wireshark的Follow TCP Stream验证创建连接的数据包。
在需要分析的数据行上点击右键,然后选择 “Follow TCP Stream”。wireshark Follow TCP Stream 功能介绍。然后你会看到如下弹窗。
上图中的数据包是有问题的。因为上面只有向服务器发送的数据包内容,而没有服务器返回的数据包内容。正常的数据交互如下图:
多次分析,都是192.168.1.2服务器没有正常返回数据。由此可以判断,是192.168.1.2服务器的问题。跟业务方沟通后,让其下线192.168.1.2服务器。持续观察,没再发现gone away的问题。由此最终确定,的确是192.168.1.2服务器的问题。