nginx 下载问题fix录--tcp分析优化

cheng029

问题表象：
        一个机房上布了nginx+下载svr
        从另外一个机房一台机器上wget下载某1.2G大小文件，一般情况下，速度都可以稳定的保持在10M-20M左右；
        但有时wget，速度只能达到100K-150K左右，且这个速度一直提升不了，也是出奇的稳定；
       
        现象补充：
        问题很奇怪，于是尝试从其他机器去wget，发现很正常，不会出现这种问题；奇怪了！！！

问题分析：
        感觉非常奇怪，速度相差非常远，但都比较稳定，一个是稳定的快，一个稳定的慢；
        流程还是有点长，wget <-> nginx <-> 下载svr <-> 存储集群
        初步分析任务 wget 和 nginx 之间应该不会有什么问题，应该比较相信他们；
        第一反应是下载svr或者存储集群哪里有问题，最常见的是内部存储集群延迟厉害；


一步一步来吧：
1，先分析wget，strace 了下wget：
        工具：strace, lsof, netstat
       
        select(5, [4], NULL, NULL, {0, 950000}) = 1 (in [4], left {0, 930000})
        read(4, "\260h ~\345\342\203\342\307\10"..., 16384) = 2896
        clock_gettime(CLOCK_MONOTONIC, {11913187, 895767462}) = 0
        write(3, "\260h ~\345\342\203\342"..., 2896) = 2896
        select(5, [4], NULL, NULL, {0, 950000}) = 1 (in [4], left {0, 950000})
        read(4, "\332\211d\322\37\27\350:"..., 16384) = 5792

        wget 用了一个连接和nginx交互，但采用了select来做监控fd
        在速度慢的情况下，strace过程中，select 会阻塞一小段时间，
        虽然比较短，但肉眼能明显感觉的到这一阻塞，这是和现象相符的；
        拿到这个tcp连接，netstat 下
        tcp        0      0 test_cl:45101        nginx_dl:80           ESTABLISHED
        果然，Recv-Q 和 Send-Q 都是空的；

        结论：wget 是正常的；

2，再来分析nginx
        工具：netstat
       
        低速情况下，连续的 netstat 这个tcp连接结果如下：
        tcp        0  94120 nginx_dl:80           test_cl:45101        ESTABLISHED
        tcp        0  62264 nginx_dl:80           test_cl:45101        ESTABLISHED
        tcp        0 102808 nginx_dl:80           test_cl:45101        ESTABLISHED
        tcp        0  79640 nginx_dl:80           test_cl:45101        ESTABLISHED
        tcp        0  82536 nginx_dl:80           test_cl:45101        ESTABLISHED
        tcp        0 102808 nginx_dl:80           test_cl:45101        ESTABLISHED
        tcp        0  92672 nginx_dl:80           test_cl:45101        ESTABLISHED

        出乎我的意料，Send-Q 一直是大于0的一个值，明显，nginx这边的数据堆积在 tcp SendBuf 里面了；
        wget接收too slow？但 wget 那边的 Recv-Q 一直是空啊；

        VS：于是和高速度的情况下做个对比，netstat 结果如下：
        tcp        0 1434149 nginx_dl:80           test_cl:41554        ESTABLISHED
        tcp        0 523928 nginx_dl:80           test_cl:41554        ESTABLISHED
        tcp        0      0 nginx_dl:80           test_cl:41554        ESTABLISHED
        tcp        0 558592 nginx_dl:80           test_cl:41554        ESTABLISHED
        tcp        0      0 nginx_dl:80           test_cl:41554        ESTABLISHED
        tcp        0      0 nginx_dl:80           test_cl:41554        ESTABLISHED
        tcp        0 1572864 nginx_dl:80           test_cl:41554        ESTABLISHED
       
        Send-Q 缓冲中数据变化非常大，最大有1.2M左右（nginx的缓冲大小设置的比较大），
        最低是0，而且有一半情况下是0；这个是和高速现象符合的；
       
        对比两种情况下，最大区别是 Send-Q 中的数据大小；
        同样的机器，同样的程序，为什么表现这么大区别？
       
        结论：突然一个念头一闪，会不会是两种情况下tcp连接窗口大小相差太远造成的；

3，验证猜想：抓窗口大小
        工具：tcpdump
       
        高速情况下，tcpdump 输出三次握手的交互包：
        14:08:13.088635 IP test_cl.57217 > nginx_dl.http: S 2882002423:2882002423(0)
                win 5840 <mss 1460,sackOK,timestamp 3326778687 0,nop,wscale 7>
        14:08:19.121903 IP nginx_dl.http > test_cl.57217: S 162476119:162476119(0)
                ack 2882002424 win 5792 <mss 1460,sackOK,timestamp 2132019999 3326778687,nop,wscale 7>       
       
        低速情况下，tcpdump 输出三次握手的交互包：
        14:04:17.882002 IP test_cl.39735 > nginx_dl.http: S 2626073064:2626073064(0)
                win 5840 <mss 1460,sackOK,timestamp 3326543489 0,nop,wscale 7>
        14:04:23.914918 IP nginx_dl.http > test_cl.39735: S 4202563613:4202563613(0)
                ack 2626073065 win 5792 <mss 1460,sackOK,timestamp 2131784792 3326543489,nop,wscale 7>       
                                                 
        呃，一样的，猜想失败！！
       
4，只能分析 tcpdump 的抓包了...       
        汗，tcpdump 后面包的 win 大小真有点看不懂啊！！！
        看了好久才看明白，真正的窗口大小是：win*(2<<wscale)
       
        tcp有个慢启动的算法，窗口会比较小，然后慢慢增大；
        低速情况下，tcpdump 窗口最后稳定在 501*(2<<7) = 60k 左右；
        而高速情况下，tcpdump 窗口最后稳定在 24576*(2<<7) = 3M 左右；
       
        另外在一台限速过的机器上进行下载，速度只能在40K左右，
                        tcpdump 窗口最后稳定在 5521*(2<<7) = 600k 左右；
       
       
5，很想准确的知道这个缓冲区大小到底多少，于是尝试用以前一个办法获取缓存区大小；
        工具：gdb，netstat
       
        低速情况下,gdb 挂住 wget
        netstat 发现最后稳定在：
        nginx ：tcp        0  45184 nginx_dl:80           test_cl:41750        ESTABLISHED
        wget  ：tcp   189136      0 test_cl:41750        nginx_dl:80           ESTABLISHED
       
        高速情况下，gdb 挂住 wget
        nginx ：tcp        0 3558289 nginx_dl:80           test_cl:46488        FIN_WAIT1
        wget  ：tcp   3759098      0 test_cl:46488        nginx_dl:80           ESTABLISHED
       
        结论：明显低速情况下的wget接收缓冲远远小于高速情况下的接收缓冲大小！！
                         基本和步骤4得到的结论差不多，也印证了这一结论；
       
6，搞了好久，还是没明白为什么，开始有点怀疑是后端svr的问题；
        呃，突然想起，如果单独测试 wget+nginx 怎么样？会不会也出现这种问题，
        于是在nginx目录下放了个1.2G的文件，然后wget；
        速度那是杠杠的快啊，50-60M，试了10多次，都没任何问题，信心动摇了；
        侥幸的心理驱使不停的按下去，突然，出现了个 200k 就不动了，最后稳定在了 135K 左右；
        终于再次且肯定确定的排除了业务svr的问题；
        是网络环境或者是机器的问题；
       
        这种问题，按以往的做法，直接丢给运维...
        呃，都搞了一下午，那就接着搞吧，不是业务svr的问题，也算是个问题吧，
        先尝试怎么发现这个问题吧，虽然心理没底；
       
        tcpdump 发现窗口最后稳定在 829*(2<<7) = 100k 左右；
       
7，仔细分析对比高速和低速下的 tcpdump 输出，差别在于：
        低速的状况下，多了下面的一些包：
        test_cl.59114 > nginx_dl.http: . ack 6087 win 145 <nop,nop,timestamp 3340680129 2145921967>
        test_cl.59114 > nginx_dl.http: . ack 6087 win 145 <nop,nop,timestamp 3340680129 2145921967,nop,nop,sack 1 {7535:8983}>
        test_cl.59114 > nginx_dl.http: . ack 6087 win 145 <nop,nop,timestamp 3340680129 2145921967,nop,nop,sack 1 {7535:11879}>
        nginx_dl.http > test_cl.59114: . 6087:7535(1448) ack 477 win 54 <nop,nop,timestamp 2145921988 3340680129>
       
        test_cl.59114 > nginx_dl.http: . ack 6087 win 145 <nop,nop,timestamp 3340680129 2145921967,nop,nop,sack 1 {7535:13327}>
        test_cl.59114 > nginx_dl.http: . ack 6087 win 145 <nop,nop,timestamp 3340680149 2145921967,nop,nop,sack 1 {7535:14775}>       
        test_cl.59114 > nginx_dl.http: . ack 6087 win 145 <nop,nop,timestamp 3340680149 2145921967,nop,nop,sack 1 {7535:16223}>
        test_cl.59114 > nginx_dl.http: . ack 6087 win 145 <nop,nop,timestamp 3340680150 2145921967,nop,nop,sack 1 {7535:17671}>
        test_cl.59114 > nginx_dl.http: . ack 6087 win 145 <nop,nop,timestamp 3340680150 2145921967,nop,nop,sack 1 {7535:19119}>
        test_cl.59114 > nginx_dl.http: . ack 6087 win 145 <nop,nop,timestamp 3340680170 2145921967,nop,nop,sack 1 {7535:20567}>
        test_cl.59114 > nginx_dl.http: . ack 6087 win 145 <nop,nop,timestamp 3340680170 2145921967,nop,nop,sack 1 {7535:22015}>
        nginx_dl.http > test_cl.59114: . 6087:7535(1448) ack 477 win 54 <nop,nop,timestamp 2145922209 3340680170>
       
        另外，包里面还有些类似这样的重复 ack；
        test_cl.59114 > nginx_dl.http: . ack 618591 win 501 <nop,nop,timestamp 3340683568 2145925407>
        test_cl.59114 > nginx_dl.http: . ack 618591 win 501 <nop,nop,timestamp 3340683568 2145925407,nop,nop,sack 1 {620039:621487}>
        test_cl.59114 > nginx_dl.http: . ack 618591 win 501 <nop,nop,timestamp 3340683568 2145925407,nop,nop,sack 1 {620039:622935}>
        test_cl.59114 > nginx_dl.http: . ack 618591 win 501 <nop,nop,timestamp 3340683589 2145925407,nop,nop,sack 2 {620039:622935}{624383:625831}>
        nginx_dl.http > test_cl.59114: . 618591:620039(1448) ack 477 win 54 <nop,nop,timestamp 2145925448 3340683589>
        test_cl.59114 > nginx_dl.http: . ack 618591 win 501 <nop,nop,timestamp 3340683589 2145925407,nop,nop,sack 2 {624383:627279}{620039:622935}>       
       
        tcp的慢启动和拥塞算法里面有这样一段机制：
        “由于我们不知道一个重复的ACK是由一个丢失的报文段引起的，还是由于仅仅出现了几个报文段的重新排序，
        因此我们等待少量重复的ACK到来。假如这只是一些报文段的重新排序，则在重新排序的报文段被处理并产生
        一个新的ACK之前，只可能产生1 ~ 2个重复的ACK。如果一连串收到3个或3个以上的重复ACK，就非常可能是
        一个报文段丢失了。于是我们就重传丢失的数据报文段，而无需等待超时定时器溢出。这就是快速重传算法。
        接下来执行的不是慢启动算法而是拥塞避免算法。这就是快速恢复算法。”
       
        对比抓包输出，知道：
        6087-7535 这一段数据，接收方（即wget程序）没收到，但却收到了后面一些包
        发送方（即nginx）连续收到了3个这样的ack，知道包应该是丟了，于是立即重发 6087-7535 这段数据（即第四行）
        但是又连续连续7个ack过来，于是nginx再次重发这段数据；
       
        因为丢失了包，于是慢启动被中止了，进入了拥塞避免算法...
        对后面的log进行分析，发现这样的情况时断时止，导致窗口根本上不去；


问题终于发现了：
        client本身系统或者中间的路由有问题，导致tcp包有很多都乱了（也有可能是真的丢了）
        但奇怪的是这种丢包仅仅针对已经建立的tcp连接；

BTW：数据流服务器真的挺需要依赖 tcp 性能分析以及优化的，包括上传，下载等等...

outlook

我抢、我抢、我抢沙发~

yinl_li

只有假货是真的，别的都是假的!

lihu129c

我真想亲口管你爷爷叫声：爹！

fateame

小手一抖，钱钱到手！

haloi

人生自古谁无死，啊个拉屎不用纸!

woxio770

有事秘书干，没事干秘书!