使用tcpdump抓包并通过wireshark图形化工具来分析网络问题

2017-09-28

发现问题

最近后台告警信息比较多, 大概看了一下, 发现一些很正常的请求偶尔会有几百毫秒甚至一两秒的耗时. 分析了一下代码, 应该不是代码的问题, 于是在mysql创建连接处加了一个耗时统计, 果然, 罪魁祸首就是创建mysql连接导致的.

编写test重现问题

为了确认是否是单纯的创建mysql连接导致,而不是其他的因素影响,我单独写了一个 shell 脚本, 不停的创建连接,然后统计耗时,一旦超过预设值100ms就打印告警信息并停下来. 执行脚本,果然与预想中的一样,创建了几千个连接后,就出现了一个耗时特别长的请求.

先使用tcpdump开始抓包,然后执行脚本.
因为测试脚本的逻辑是一旦发现耗时过长的连接,马上停止执行,所以针对端口进行抓包,最后几个包一定是有问题的.

脚本代码如下:

#!/bin/bash
# arg1=start, arg2=end, format: %s.%N
function getTiming() {
    start=$1
    end=$2
    start_s=$(echo $start | cut -d '.' -f 1)
    start_ns=$(echo $start | cut -d '.' -f 2)
    end_s=$(echo $end | cut -d '.' -f 1)
    end_ns=$(echo $end | cut -d '.' -f 2)
# for debug..
#    echo $start
#    echo $end
    time=$(( ( 10#$end_s - 10#$start_s ) * 1000 + ( 10#$end_ns / 1000000 - 10#$start_ns / 1000000 ) ))
	echo $time
}
for a in $(seq 1 10000)
do
start=$(date +%s.%N)
/usr/bin/mysql -utest -p123456  -h 192.168.0.11 -Dtestdb -e "quit" > /dev/null 2&>1
end=$(date +%s.%N)
elapsed=`getTiming $start $end`
if [ $elapsed -gt 100 ]
then
echo $start "elapsed:" $elapsed
exit
fi
done

抓包命令:

1	sudo tcpdump -i any -s 0 -w /var/tmp/1.cap port 3306

抓到包后发现,很难找到真正耗时的那个请求,因为创建的连接数太多了,而每一个请求并没有表示耗时的属性,只能通过肉眼观察一个回报和其对应的请求之间相隔多久来得出耗时. 而且不知道为什么, 脚本中的这一行代码

1	/usr/bin/mysql -utest -p123456 -h 192.168.0.11 -Dtestdb -e "quit" > /dev/null 2&>1

在抓包信息中显示,找不到db 2 这个库. -e “quit” 会导致这个错误,也不知怎么回事.

最后想到一个办法,直接使用C++写客户端,虽然麻烦一点,但是可以知道出问题的连接的端口号,这样就可以精确查找这个端口号的所有收发包了.同时也可以精确的计算一个连接创建的耗时而不是像脚本里面那样,计算了创建的耗时加上断开的耗时.

使用C++编写测试客户端

以下代码使用了google test 框架和 mysql c driver

for(std::size_t i = 0; i != 100000; ++i) {
  auto now = TNOWMS;
  auto _pstMql = mysql_init(NULL);
  auto elapsed_mysql_init = TNOWMS - now;
  auto now1 = TNOWMS;
  //建立连接后, 自动调用设置字符集语句
  if (mysql_options(_pstMql, MYSQL_SET_CHARSET_NAME, "utf8")) {
    throw TC_Mysql_Exception(string("TC_Mysql::connect: mysql_options MYSQL_SET_CHARSET_NAME ") + "utf8" + ":" + string(mysql_error(_pstMql)));
  }
  auto elapsed_options = TNOWMS - now1;
  auto now2 = TNOWMS;
  if (mysql_real_connect(_pstMql, "192.168.0.11", "test", "123456", NULL, (int)3306, NULL, 0) == NULL) {
    throw TC_Mysql_Exception("[TC_Mysql::connect]: mysql_real_connect: " + string(mysql_error(_pstMql)));
  }
  auto elapsed_conn = TNOWMS - now2;
  auto elapsed = TNOWMS - now;
  if (elapsed > 500) {  //如果创建连接耗时500以上
    auto localIpPort = getIPHostBySocketFD(_pstMql->net.fd, true);  //获取当前连接的local port和peer port
    auto peerIpPort = getIPHostBySocketFD(_pstMql->net.fd, false);
    DEBUGLOG << "local|" << std::get<0>(localIpPort) << "|" << std::get<1>(localIpPort) << "|peer|" << std::get<0>(peerIpPort) << "|" << std::get<1>(peerIpPort) << "|mysql_init|" << elapsed_mysql_init << "|elapsed_options|" << elapsed_options << "|elapsed_connect|" << elapsed_conn << std::endl;
  }
  ASSERT_LT(elapsed, 500);
  mysql_close(_pstMql);
}

编译执行之后, 捕获到了一个端口号为 58818 连接耗时过高

通过以上截图中的时间可以看到, 主要是 Mysql协议的登录请求导致耗时过高.

接下来,就可以去查查Mysql登录的回包为啥会这么慢了.抓包这部分的工作就算是完成了.