通过tcpdump和wireshark分析应用慢请求问题

最近通过报警发现应用频繁有超过1s的慢请求,通过查看日志、tcpudmp和wireshark最后定位是网络问题,在排查过程中也参考了网上的很多文章,但是写的都不是全,现在有空分享一下问题排查的一些经验,希望对遇到类似问题的码农们有所帮助,具体排查步骤如下:

  1. 查看程序日志,程序中对超过100ms的请求都有日志输出,通过查看日志发现有大量的数据库和redis超时
  2. 查看redis的慢请求,redis并没有发现慢请求日志,redis慢请求查看的方法具体可以参考redis的文档:http://doc.redisfans.com/server/slowlog.html
  3. 查看数据库的慢查询日志,数据库也没有相应的慢请求
  4. 最后开始怀疑时间是耗费在连接数据库和redis的网络连接上,通过tcpdump命令dump出系统上一定时间的tcp请求,具体命令是
    tcpdump   -i  eth0  -s  0  -w  tcp_245.pcap   host  192.168.1.245
     其中-i参数指定抓取哪个网卡上的tcp请求,-w参数指定dump的文件目录 host参数指定抓取该ip发出和收到的请求,-s 0 : 抓取数据包时默认抓取长度为68字节。加上-s 0 后可以抓到完整的数据包,具体其它命令参数可以通过tcpdump --help查看
  5. 通过wireshark分析dump出来的tcp请求,首先需要在wireshark中找到想要的请求,这时需要通过IP和端口号先过滤出所有的redis请求,具体截图如下:
    通过tcpdump和wireshark分析应用慢请求问题
     通过tcpdump和wireshark分析应用慢请求问题其中ip.dst == 10.10.1.1 指定了redis所在的服务器ip, tcp.dstport == 7522指定了redis的端口号,过滤后明显发现有TCP Retransmission,即网络重传
  6. 为了确认是因为重传带来的时间损耗,需要过滤该次请求的完整记录,具体步骤:选择RetransmissionI的行--右键--选择追踪流--TCP流,截图如下:
    通过tcpdump和wireshark分析应用慢请求问题
     通过tcpdump和wireshark分析应用慢请求问题从图中可以看出重传的tcp包中的seq和ack跟上面tcp包中的seq和ack是完全相同,数据包的大小也完全一样,可以确认是同一个tcp请求发生了一次重试,但是从时间上看延迟了200ms,这只是其中的一个TCP请求,如果一个HTTP请求中会有10个左右的数据库和redis请求延迟时间会达到2s以上。

相关推荐