起因

事情的起因是我们给线上的一个服务新加了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的官方调优指南中，也有一项针对这个配置的调整，不经历这些幺蛾子，还真不能理解这些看似简单的一句配置后面的故事。

后记

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