欢迎光临
我们一直在努力

arp缓存超时 网络问题追查记录 unres_qlen

起因

事情的起因是我们给线上的一个服务新加了30台服务器,然后就有用户反馈说我们的查询性能开始变得不稳定,一些平时很快的请求经常要卡好久才能返回。照理说加机器服务应该变得更快才是,怎么会变得更不稳定呢,这让我们一开始也不是很愿意相信这个事实。直到我们自己也试着查了几次,确实有用户反馈的不稳定的现象,有时候query能在几百毫秒就返回结果,有时候却需要10几20秒之久。追查问题开始之前,我先介绍下系统的服务模型,系统由broker和worker组成,每台机器都有broker和worker两个进程。broker负责接受用户请求,然后将请求转发至需要的worker上,等这些worker返回结果后对这些结果进行merge最终返回给用户。系统最前端使用了VIP对broker进行负载均衡。

表面原因

由于我们已经对系统接收到的所有query的运行情况进行了埋点和耗时统计,表面原因也很容易定位,请求确实耗在了我们系统内部,就在broker把请求发送给worker的时候。先插一段broker访问worker的核心伪代码:

for worker in all related workers:
    pool = setup_connection_pool(worker) // 对每个worker初始化一个连接池,并且发起连接请求
    connection = get_connection_from_pool(pool) // 从连接池中随便拿一个连接
    wait_connection_ready(connection) // 等待连接真正可用
    send_request(connection)

在我们对这些代码增加了一些耗时埋点和分析后,原因最终确定在了第4行wait_connection_ready这,经常需要花上3秒左右的时间,才能等这些连接最终建立成功。那为什么一个query会花上10几20秒?这是因为我们的query几乎会涉及到所有的worker,经常会有那么几个worker会复现这个现象,累加起来后就达到这么长时间了。

现象分析

第一反应是,一个connection没理由需要花上3秒时间才能真正建立,是不是等待连接建立的代码写错了,或者是内部使用了一些锁导致哪里被不正常的lock住了。仔细排查后我们排除掉了这个原因,我们只是简单的使用了Netty的ConnectionFuture,在网上搜索了一番也没见有人反映过跟着类似的问题,要是这么容易复现那Netty也未免太挫了点。虽然在研究代码过程中,基本已经排除了有任何锁或者IO的行为会引起这个耗时的发生,但是为了保险起见,我还是去实现了一个比较纯粹的Netty Http Client,来验证是否能复现这个问题。核心代码就下面几行:

for (String host : hosts.split(",")) {
    System.out.println("setup " + size + " connections with " + host);
    final AtomicInteger completedSize = new AtomicInteger(0);
    long start = System.nanoTime();
    for (int i = 0; i < size; ++i) {
        ChannelFuture future = bootstrap.connect(new InetSocketAddress(host, port));
        future.addListener(new ChannelFutureListener() {
            @Override
            public void operationComplete(ChannelFuture future) throws Exception {
                completedSize.addAndGet(1);
            }
        });
    }
    while (completedSize.get() != size) {
        Thread.sleep(1);
    }
    long end = System.nanoTime();
    System.out.println("setup " + size + " connections, used time: " + (end - start) / 1000000.0 + " ms");
}

为了模拟原始代码的连接池的行为,这里选择对一台机器同时建立好几个连接。在使用这段代码访问线上的worker进程后,问题果然还是复现了。比如对每个worker建立10个连接,有些worker在几个毫秒内就成功建立,但总有些worker需要花费3秒才能建立成功。同时,在使用这个简单的程序复现问题的过程中,还发现了一个一开始并未注意到的现象:一台机器总是第一次对其他机器发起连接请求时才会有这个问题。如果短时间内程序跑上第二遍,第三遍,就又观察不到这个现象了。

机器问题?

其实在调查过程中,有个疑问一直徘徊在我心头,为什么老机器没问题而新加了30台机器后就出问题了?而且在上面复现的过程中,如果我从老机器发起连接请求,都能很快的就返回,而使用新机器发起连接请求,就总会有那么几台机器需要耗时3秒,而且这些耗时久的,也都是新要来的机器。这让我不得不怀疑新给的这批机器是否有问题。于是我在开着tsar实时监测网络情况下运行了我的复现代码,很快就发现了不对劲。这是我的程序的输出:

setup 10 connections with host1
setup 10 connections, used time: 3.173193 ms
setup 10 connections with host2
setup 10 connections, used time: 3001.584501 ms
setup 10 connections with host3
setup 10 connections, used time: 3.232675 ms
setup 10 connections with host4
setup 10 connections, used time: 3001.711274 ms
setup 10 connections with host5
setup 10 connections, used time: 7.295985 ms

对应的这段时间内tsar的输出:

两台机器建立连接花了3秒,对应了两次网络重传率的飙高,我对机器问题的怀疑又新增了几分。为了有更确凿的证据,我使用了tcpdump来对网络传输的包进行了分析,情况也正如我所预料:

看来确实是机器问题了,带着查清问题的喜悦和一丝对机器的吐槽,我拿着这些证据找了PE和公司里的网络支持。

真的是机器问题?

接下来的几天,我一直在等着网络的同学来向我”自首“,承认他们的这批机器存在网络问题,有可能是哪里网线松了?也有可能是搭建网路时哪里的配置没弄对?但我没等来这一天,虽然网络支持的同事也一直很尽心尽力的在帮我定位问题,但是却始终找不到问题的根源所在,硬件检测也似乎没有什么发现,什么网线松了之类的也只不过是我的无端臆想。从一开始定位到问题的激动情绪慢慢恢复过来的时候,我也开始感觉到了一丝的不对劲。既然那边还迟迟没有结论,我觉得有几个疑问还是要继续的进行一下探索。为什么是3秒?为什么是我们的服务(因为这批机器在给我们之前跑过其他服务,也没见同事有过这个抱怨),如果是网络问题,应该老早就体现出来了才对。难道是我们的worker端的问题?虽然我觉得这个概率不大,因为之前我们的服务已经在线上跑过一阵,从来没有发生过这种现象。不过想到这点了,还是有必要做一下验证。验证的办法很简单,把我们的worker换成其他成熟的http server,看还会不会有这个问题。想了下,最成熟可靠又简单的莫过于nginx了,于是我在这批机器上全部都起了nginx服务,并使用我上面写的客户端来连接这些nginx。问题还是复现了!到目前为止,这个问题已经完全与我们的线上服务撇清了关系,理了理思路,总结了下目前为止发现到的现象:

  • 使用一个简单的Netty Http Client对一台nginx服务器同时发起多个http连接请求,会有比较大的概率需要3秒左右的时间才能成功建立连接
  • 在短时间内再使用这个client对同一台服务器发起多个http连接,所有的连接都能瞬间建立
  • 在休息一段时间后再次实验,又能观察到连接耗时3秒的现象

这个时候,网络的同学也基本上给出了他们的结论,网络没有问题。至此,事情又陷入了僵局。。。

重温TCP

一边是一个成熟的http server,另一边也是一个成熟的java开源网络库,当在它们之间建立几个连接的时候,却需要花上整整3秒的时间。这要是出去说估计都没人信,却真真切切的发生在我的眼前。既然硬件没有问题,网络的设备也没有问题,用到的两个东西出问题的概率也微乎其微,那看起来很有可能是内核或者tcp的一些参数设置的问题了。请来了公司的网络大牛@灵皋帮忙一起定位问题,自己也开始一边复习tcp的基础知识,一边一遍一遍的使用tcpdump进行抓包分析,希望能看到新的一些蛛丝马迹。这里推荐下陈皓写的TCP 的那些事儿(上)TCP 的那些事儿(下),通俗易懂也不失一些深度。不过在这更正下那篇文章中关于SYN超时的结论,SYN包的超时时间是基于RTT并且使用一个比较复杂的公式计算得出的,在我们的服务器上第一次超时时间一般是3秒(参见上面的tcpdump图),而不是该文中说的是1秒。虽然学习并巩固了不少tcp相关的知识,但是却没有任何一点看起来和这个问题有关。TCP拥塞?才几个syn包有什么好拥塞的。小包合并?是有可能,但是就算有合并一般也就等个几十毫秒也就放了,况且在我们的现象里确实有丢包的情况发生。SYN攻击防范?才几个SYN包有啥好防范的,而且我们的服务器已经把net.ipv4.tcp_max_syn_backlog这个参数调的比较大了。虽然没有获得有关这个问题的直接帮助,但是顺势学习了一把tcp的基础知识,感觉还是收获满满,要不怎么大家都说查问题是最好的学习途径呢。
不过随着追查的深入,问题的一些表现也变得越发诡异了起来。在某些复现的场景下,并没有观察到丢包的现象,取而代之的SYN包的乱序。如下图所示:

虽然在时间上也是相同的延迟了3秒,但却没有检测到丢包或者重传的现象,反而有一些让人更想不通的表现。一般来说,我们在同时建立好多连接时,客户端的端口号会是连续并且递增的,但从图中可以看到,端口在3秒后发生了回滚,看起来客户端在3秒后才发起了本应该在3秒前就应该发出的连接请求。还有一个是tcp包头里的时间戳:TSVal,也在3秒后发生了回滚,如果这几个SYN包是3秒前应该发的那批,那为什么当时没发?为什么也没有检测到TCP重传或者丢包?
虽然出现了更多似乎没法解释的现象,但是一遍一遍的tcpdump还是有了新的发现。

ARP

在复现的tcpdump中,经常能发现类似下面的现象(但不是全部):

ARP是啥?先来看一段百度百科上的定义:

地址解析协议,即ARP(Address Resolution Protocol),是根据IP地址获取物理地址的一个TCP/IP协议

OSI模型把网络工作分为七层,IP地址在OSI模型的第三层,MAC地址在第二层,彼此不直接打交道。在通过以太网发送IP数据包时,需要先封装第三层(32位IP地址)、第二层(48位MAC地址)的报头,但由于发送时只知道目标IP地址,不知道其MAC地址,又不能跨第二、三层,所以需要使用地址解析协议。平时只关注TCP/IP一类的东西,对再底层的东西知之甚少,以前学过的基本也全还给老师了,正好趁此机会再复习复习。ARP的工作原理比较简单,但是有一点比较关键,ARP是有缓存的,缓存了本地以太网内的一些IP和MAC地址的映射关系。想来也是,如果每次要传输数据时都使用ARP协议确定对方的MAC地址,那效率岂不是太低了。既然是缓存,那肯定会有缓存更新和淘汰算法,具体可以参考这篇StackOverflow上的问答帖。基本结论是,arp的缓存一般10分钟左右会淘汰。咦,10分钟?好像我之前在复现问题的时候,同一台机器在第一次复现之后,一般都得等上10分钟左右才会复现第二次。另外,新给的机器IP都是连续的,网络的同学提过这批机器应该是挂在同一个路由器下的,这也验证了这些机器之间会互相进行ARP请求,但和老的那些机器之间就不会有ARP,因为属于不同的路由器,在发请求的时候在路由表的指引下应该直接就通过网关出去了。我隐隐的觉得,这个问题,肯定和这个ARP有关系。

真相

同时在另一边,在@灵皋大神的帮助下,也使用了不少平时接触不多的工具来定位这个问题,iptable,ip monitor等。通过分析这些工具的表现,矛头也渐渐的向ip和mac这个方向靠拢了,但最后的那一层窗户纸却还是没有办法捅开。直到我百无聊赖的又试了试我的复现程序。因为之前都是同时建立10个连接来复现这个问题的,我就是想试试跟连接数是否有关系。实验结果表明,如果同时建立的连接数不超过3个,就完全不能复现这个现象。我随口跟@灵皋大神提了下这个最新的现象,同时把之前跟ARP的种种疑点跟他说了一遍,他终于捅开了这最后一层窗户纸:“好像arp那边有个包的缓存队列,好像默认值就是3”。
这句话犹如醍醐灌顶,我赶紧再去仔细查了查arp的man page,终于在一个不起眼的小角落发现了一句话:

unres_qlen (since Linux 2.2)
    The maximum number of packets which may be queued for each
    unresolved address by other network layers.  Defaults to 3.

尼玛!原来就是这货!所有的现象在这一刻终于都得到了解释,为什么有有时候有丢包的现象,有时候却是单纯的重传,为什么3个连接以下就不会出问题。一次ARP请求虽然比较快,但还是需要一些时间的,在这短暂的时间内如果有对目标IP的多个包,会被系统缓存在一个队列中,如果队列放不下了的话就直接丢掉,连tcpdump也抓不到这个丢弃的行为。丢的有可能是发起TCP连接时的SYN包,也可能是第二次握手里server返回的SYN-ACK包。这些诡异的现象大致可以用下面这几种情况来描述(客户端是A,服务端是B,我用“认识”来描述该机器的ARP的缓存中是否有对方IP的存在):

  1. A认识B,B也认识A: 这种情况下的通信完全不会有问题。
  2. A不认识B,B认识A: 如果A在ARP请求成功前请求超过3个SYN包,tcpdump表现为只成功发出过3个SYN,被丢掉的几个SYN会表现为从未发出,但是在3秒后会进行重传。这就是上面观察到的端口和时间戳回滚的现象。
  3. A认识B,B不认识A: A的所有SYN包都能顺利的发出,但B在回SYN-ACK前需要发起ARP请求。如果在ARP成功前有超过3个SYN-ACK包堆积,则只能有3个能顺利回到A。tcpdump表现为A的有一些SYN丢包,在3秒后进行重传。
  4. A不认识B,B不认识A: 最复杂的情况,上面两种丢包或者重传都有可能发生。

据悉,内核已经在之后的版本修改了这一参数,不使用包的个数来限定队列大小,而是使用包的字节数来作为限制条件。确定了问题的根源后,对应的解决办法就很简单了,修改系统的配置文件即可。其实redhat的官方调优指南中,也有一项针对这个配置的调整,不经历这些幺蛾子,还真不能理解这些看似简单的一句配置后面的故事。

后记

一个看似简单的线上问题,其实底下却蕴含着这么多底层的网络和内核知识。有幸在工作中能接触到这些可能其他人几乎不可能碰到的问题,随着问题表现的牵引,也拿起了很多以前可能学过但早就还给老师了的知识。通过查问题学到的东西,都是最最难忘的。

赞(0) 打赏

评论 抢沙发

评论前必须登录!

 

觉得文章有用就打赏一下文章作者

支付宝扫一扫打赏

微信扫一扫打赏