去爬黄山

上周去爬了黄山,浅记一下,这篇又是流水账了。

Day 1

坐高铁来的黄山北站,已经是下午2点了,吃的不多,只有俩超市,以及一个 KFC,在 KFC 随便吃了点东西,然后从黄山北站到汤口镇住一晚。

汤口镇在黄山脚下,去爬黄山的人基本上第一天都会选择住在这里。从黄山北站到汤口镇巴士 30 元一人,可以选择拼车,一人 40,速度快 20min 左右,巴士发车速度 40min 一班,需要在微信小程序买票。黄山的巴士已经各种门票都是用小程序的。

我们选择的是巴士,送我们到景区的南大门,酒店一般都提供接送服务(3km 以内)。这里民宿比较多,我们是从飞猪订的一个民宿,因为装修时间是 2020 年,觉得会干净一些。结果到了之后发现这个民宿不叫这个名字,在携程上是叫做另一个名字,评分并不高。是同一个酒店贴了两个名字挂在两个平台卖……也不是很干净。

安顿好之后就打车去汤口镇中心吃了顿饭,买了点第二天爬山用的东西。打车 3km 花了 7块钱(这物价!)

读者如果去的话,考虑买的东西有:

  • 自热饭:很多超市都卖,作为第二天的午饭。但是不推荐海底好自热火锅,我觉得不好吃,而且这玩意消耗很多水,不太好搞;
  • 水:我第二天是背了 6 瓶上去的,我以为山上得 20 块钱一瓶吧,结果发现山上才 8 块钱一瓶,这比新加坡的 711 还便宜一半!没必要背这么多;
  • 木头棍:我们自带了登山杖,不过我也没用上,黄山现在有了两个索道,其实非常轻松。坐索道上去之后,爬山就跟徒步一样简单。但是如果买的话,2 块钱一根就能买,有卖 5 块的 10 块的,可以砍到 2 块钱;
  • 各种巧克力,零食:自己比价吧,汤口超市的物价都很贵(相比于打车才6块钱这个消费水平来说),不同超市不同产品差价一两块;

晚上吃饭在美团买了个套餐,找了家评价还算高的饭店。

一共 157 元
  • 石耳鸡汤:推荐,很好喝;
  • 臭鳜鱼:徽菜特色,不好吃,接受不了;
  • 毛豆腐:还可以,但是后面看到了是怎么制作的,我也接受不了了;
  • 笋干烧肉煲:挺好吃。

这里石耳可以试一下,第一次吃。种竹子特别多,所以笋类的菜肴也很多。

不过徽菜很咸,可以跟老板说下不要太咸。

Day 2:爬黄山

爬黄山的路线选择挺多,所以前一天要制定好计划,至少要大体了解下。也没必要太详细,可以根据第二天体力,天气,景区人数等随机应变。

黄山路线图

有一个选择是在山顶住一晚,看日出,第二天再下山,会比较轻松。但是考虑到我们穷山顶的酒店性价比太低,不是很干净,又什么都贵,看日出的话还要准备厚衣服,我们打算当天下山。

所以感觉时间比较紧张,就早早起床了,7点就到了景区。到的时候看到实际进山人数才 2500 左右,我们算比较早的。

当天预约人数 17K,不算太多

我们当天的路线以及实际花费(每人价格)如下:

  1. 黄山景区大门门票,190 元
  2. 去南大门做巴士到索道,19元
  3. 坐云谷索道上山,80元
  4. 去西海大峡谷,路线基本上是一路下山,然后坐火车回去山上,100 元
  5. 坐玉屏索道下山,90元
  6. 坐巴士到南大门,结束,19元(注意只有这里要排队线下购买纸质票,不支持微信购票)

可以看到,相对于当地的物价来说,黄山景区的门票并不便宜。

值得一提的是,(1) 的黄山门票自验票之后 3 天有效,后面可以继续爬,或者住在山上。但是其他巴士,索道等,坐一次买一次。

一开始看到网上说一天的话,西海大峡谷来不及去,需要至少 4 小时。但是当天我们上到西海饭店的时候才 11 点左右,感觉完全来得及,于是决定还是去一下。后来发现非常值得,而且 2.5 个小时这一圈就转完了。可能是因为我们这天人数不多吧。

坐索道上山
索道出来之后的风景

第一个景点是所谓的“猴子观海”。其实啥也看不到,这天雾挺大的。

猴子观海

我从网上找了个没有雾的图,看起来像这样。

图片来自网络

但是是实话,我对山上这种人们“想象”出来的风景不太感冒。我的家乡也有很多山,可能是觉得作为一个景区没有很多景点的话有点丢面子吧,几乎大大小小的山都有这种“因势利导”的景点,比如大手啦(佛手?),乌龟啦,大象啦,猴子啦,观音啦。游客真正到了那个地方的时候,要花好些心思才能体会到这些景点作者的主意,大多是让人有些失望的。所以现在爬山,类似这种奇形怪状的石头,对我来说,不看也罢。

这张应该是在光明顶附近拍的
好像也是个景点,但是如上所说,我连名字都忘了
路上有很多松树。

没有文化的我,以为每一个山上都有迎客松(还以为是一种松树),今天才知道,迎客松特指黄山上的一颗招手的松树,虽然路上见过类似的松树也不少。

这才是大名鼎鼎的迎客松
山上的午饭,以自热饭为主。

还遇到一组新加坡人,这组人穿着比较开放,我跟媳妇说,这肯定是新加坡的。她不信。结果在自动售货机前,听到他们在买 100 Plus,我们偷笑(一种只有东南亚才有的功能饮料)。

午饭的时候他们买的自热饭找不到水,问我们的水哪里来的,我就送了他们一瓶,毕竟带了这么多上来。

还是光明顶附近
吃饭的地方看到的景色
从远处看我们走过的路

如果走不动了,可以打的士。

有人按照距离和价格算了一下,折合七毛钱一步。哈哈。

吃完饭之后,下午的路上经过了一场雨。爬黄山如果遇上下雨,还是体验很差。好在只下了一会。

下山之后,我们来到了宏村。

民宿选在了宏村里面。这次选对了(媳妇选的)。非常干净,细节考虑周到,老板是个北京人,非常热情,也很健谈。(其实,宏村就是一个北京的公司在经营)

我问老板怎么一个北京人跑到南方开民宿了,老板说在北京上班得罪领导干不下去,就出来旅游,觉得这地方不错,就留下了。2019年的时候,还有三家店,但是疫情3年,压力很大,关闭了两家,只剩这一家了,一共只有7间客房。

宏村的门票也是 90 多块钱,如果住在村子里,进入大门之后可以打电话让民宿老板来接,这里巷子多,难找,老板一般都会来接的。

Day 3 宏村

雨后的宏村就很漂亮了,下山的那一晚和第二天,我们都待在这里。

宏村大门进入的景色

这天不知道有什么事件,很多学生在这里写生,都到哪里都是画板和写生,我和媳妇一路上看风景,也看这些孩子画的画。

月沼
宏村的巷子,商业化非常严重了,基本上就是一个古镇装修的商业街,之前的居民要么开民宿,要么卖茶叶

这就是毛豆腐,这个爷爷每次路过,他都在炸这玩意。

看到炸之前这毛茸茸的样子,再也不敢吃了。

就先写这么多吧。

文笔也不好,不知道自己写了些啥,权当写着玩,图一乐。

 

是谁杀了我?

今天遇到的一个问题,记录一下。

起因是同事告诉我有两台机器上面的 node-exporter 挂掉了。

收到工单,来活了

我去看了下,确实挂了,这个进程是跑在 systemd 上的,就去 journalctl 看了下日志,发现日志很神奇:

观察最后三行,发现这个进程实际上是启动成功了,都打出来 Succeeded 了,但是之后立即退出了。

为什么会这样呢?我先查了下内存,发现用的一直很低,也没有 OOM 日志,所以应该不是 OOM。机器的 CPU 和磁盘其他指标都正常,应该不是硬件问题。

我不在 systemd 下面跑,直接在 shell 上跑这个进程,发现是一切正常的。这说明不是这个进程自己退出的,可能是 systemd 的问题,或者被其他什么东西干掉了。

既然这个进程没有自己退出,其他人要想停止它的话,只可能是给他发送信号。所以接下来我用 killsnoop (BPF 写的一个程序)看下这个是谁给我的进程发了信号,发送的是什么信号。

下面是启动日志,根据 pid 可以看到上面 killsnoop 显示出来,谁给这个进程发送了信号

可以看到,正是 systemd 给它发送了 15 和 18 信号。15 是 SIGTERM,应该正是这个信号结束了我的进程。

那么为什么 systemd 刚启动就要给我发这个信号呢?我想到的一种情况是进程启动之后 fork 了一份,parent process 退出了,于是 systemd 就把剩下的进程都杀了。但是考虑到其他机器一样的配置运行是正常的,并且 node-exporter 据我所知没有这种 fork 的逻辑,所以不太可能是这种情况。但是我决定还是验证一下,这里我用 execsnoop 来检查。这个 eBPF 程序可以看到机器上跑的所有命令(spawn 的进程历史)。

发现一个 systemctl stop node-exporter 命令

好家伙,没看到 node-exporter fork,却看到一个诡异的 systemctl stop node-exporter,原来有人在暗算我。

这个命令的父进程是 pid=177579,用 pstree 看看这个家伙是谁:

pstree

是个 bash 而且没有参数,是挂在 sudo su 下面的,看起来是有人 ssh 上来跑了个 systemctl stop node-exporter 就跑了。

systemctl status <pid>

strace 看看这个 bash 在干嘛:

strace 看看这个 bash 在干嘛

果然,就是 sleep 1s 然后开始杀我,不断循环。

干掉这个 bash,问题解决。

至于为啥会有人搞这么东西在上面,问了下,是野路子。

 

TCP 长连接 CWND reset 的问题分析

我在公司维护一个 service mesh 的平台,主要是代理用户的请求,用户的服务想调用另一个服务的时候,将请求发给我们的进程,然后我们转发到对应的服务。

今天收到一个用户工单,是说在一个 50ms 延迟的环境中,实际他们调用其他服务的延迟远大于 50ms,有 200ms 左右的延迟。我一看,这个问题和《TCP 拥塞控制对数据延迟的影响》这里的问题一样嘛,应该是个送分题。于是就去验证,如果发生在 TCP 建立连接的时候,有高延迟的话,那就没跑了。结果发现这个用户的 QPS 并没有那么低,我们的 TCP connection keepalive 有 60s,用户几乎每 5s 左右就会有一个请求。

这就麻烦了。这种问题最讨厌,因为运行的环境比较复杂,这种延迟问题可能是用户的问题,可能是我们平台的问题,可能是 SDN(我们用的一种 overlay 网络架构)的问题,也可能是我们的 kernel 的问题,排查起来极为困难。

好在最后定位到了原因,最后的结论让我大跌眼镜,我以为自己对 TCP 比较了解,没有想到竟然是一个我从没有听说过的 TCP 行为导致的!如果你听说过这个参数,1 分钟就可以解决问题。这里先卖个关子,不说是什么参数了,让我从这个问题最初的排查说起。

用户提交的工单里面只说 P99 延迟升高,metrics 监控系统里单个请求就可能波动 P99,所以首先要定位到有慢请求的具体的日志。根据用户的描述(中间经过了来回拉扯),我从日志 grep 到确实有 latency 高的离谱的请求。最终排除了用户那边的问题。

然后我找我们这个平台的开发去分析一下,为什么我们平台内部会额外花费这么多时间?得到的答复是“网络问题”。哎,不知道我在抱什么期望,几乎每次这种问题都是得到“网络问题”的结论(不过这一次可真的是,笑)。如果去找网络团队,说“你们网络有问题,请排查下”,人家能干嘛呢?至少得定位到网络哪里有问题,并且有证据才行。看来还得自己动手。考虑到我 tail -f 的日志也是可以看到类似的慢请求,感觉分析起来并不困难。

前面说过由于用户的请求大于每分钟一个,所以应该不是 TCP 建立连接的 overhead 了。这里,我找到一个 client-server IP 对进行抓包,等从日志观察到出现慢请求的时候,停止抓包,然后通过日志的关键字定位到抓包里面具体的 segment。因为是自己实现的 TCP 协议,所以 Wireshark 并不认识这个协议,我只好用 tcp.payload contains "request header" 来直接从 payload 里面过滤请求。

找到这个慢请求之后,发现这个 response 比较大,于是分析 tcptrace,看到的图如下(如果你看不懂这个图片的话,可以看用 Wireshark 分析 TCP 吞吐瓶颈):

途中,每根竖线的高度可以理解为一次性发送的数据多少:第一个请求中(图中第一次升高),一开始慢慢发,越发越快,这是因为 TCP 要避免出现拥塞,所以在链接刚建立的时候会 slow start,慢慢发送,如果网络能接受,就逐渐加大发送的速度,如果发生拥塞控制了(不通的拥塞控制算法不通,cubic 使用丢包来作为拥塞控制事件)就降低发送的速度。所以开始的时候 cwnd 拥塞控制窗口在慢慢打开。其中,绿线 rwnd 并不是瓶颈,它看起来比较低,是因为我抓包的时候 TCP 连接已经存在了,没有抓到 SYN 包,所以 wireshark 并不知道 window scaling factor 是多少。

但是!!为什么 2 秒之后,在发送第二个请求的时候,这个竖线的高度又从很小开始了呢?这可是同一个 TCP 连接呀,没有重建。并且也没有丢包和重传。

我以前理解的拥塞控制算法 cubic,只会在发生拥塞事件的时候缩小 cwnd。所以我以为我看错了,但是切换到 window scaling 视图,发现 cwnd 确实每个请求都会 reset。

这跟我所理解的拥塞控制算法不一样!于是我搜索“why my cwnd reduced without retrans“,却几乎没有看到有用的信息。

甚至从这个回答里确认:cubic 在 idle 的时候不会 reset cwnd。这个回答倒提到了可能是应用的问题。

于是,下一步我想排出是不是我们平台的代码的 tcp 使用问题。

我写了一段简单的代码来模拟这个行为,它作为客户端,每 10s 发送 1M 的数据,然后空闲 10s,重复发送。

在服务端用 nc 打开一个端口即可:nc -l 10121,然后在客户端运行代码:python tcpsend.py 172.16.1.1 10121,可以看到开始发送数据了:

我写了一个循环,使用 ss 一直打印出来这个连接的 cwnd 值:

while true; do ss -i | grep 172.16.1.1 -A 1; sleep 0.1; done

从这个命令的输出中,成功地复现了问题!排出了我们平台代码的问题:

为了隐藏 IP 信息,这里只截取了部分输出,可以看到在发送完上一次的 1M 数据,10s 之后重新发送的时候 cwnd 又从 10 开始了

到这里我开始怀疑是 SDN 的问题了,为了验证,我去一个简单的网络环境,纯物理网,重新跑了一次我的代码,发现 cwnd 没有重置,说明就是 SDN 的问题。

于是叫来一个网络组的同事,给他看了这个。结果他也感觉很惊讶(再次卖个关子,不是只有我一个人不知道这个行为,有了些许安慰)。认为这不应该发生。但是他又对他们的代码很有信心,认为这不可能是是 SDN 的问题。然后他突然说,这应该是网络延迟造成的问题,SDN 所在的环境本身有 50ms 的延迟,我测试的物理网却没有。

于是我去找了一个有 100ms 延迟的物理网环境测试,结果……果然不是 SDN 的问题,观察到了一模一样的现象。

这时候已经进入到未知领域了。我去打开了 chatGPT 这个废物,它说是拥塞控制算法在 idle 之后会降低 cwnd。多新鲜呐,从没听说过。

我们的拥塞控制算法就用的 cubic,于是我和这个网络的同事一起去看了 cubic 的代码。如果能看到这逻辑的话,也就一切就说得通了。

看了半天,只有几百行,又是用 eBPF 探测又是测试的,愣是没找到这个会 idle 的时候 reset cwnd 的逻辑。感觉进入了死胡同,在网上搜 cubic reset cwnd when idle 也是徒劳无功。

同事想到一个点子:我们换成 BBR,看是否可以解决问题?!

从现象来看,BBR 速度快很多。原本以为问题解决了,但是看了下我的脚本的输出,发现其实问题依然是存在的,发送完数据之后 cwnd 会降到 4,只不过 BBR window scaling 非常快,一开始发数据蹭就跳到 1384 了。

BBR 也会 reset cwnd

不过这倒是提醒我了:要么就是所有的算法都实现了这个 reset cwnd when idle 的鬼逻辑,要么,这根本不是算法实现的,而是系统实现的!

考虑到看了一下午 cubic 的代码了,我更倾向于后者。

接下来该怎么做呢?总不能把协议栈的代码看一遍吧。

这时我靠直觉做了一个动作,我把系统 TCP 相关的配置打印出来,sysctl -a | grep tcp ,想看看有没有线索,结果一个 net.ipv4.tcp_slow_start_after_idle 直接就点醒了我。这不就正是我们遇到的问题么?

net.ipv4.tcp_slow_start_after_idle 参数,默认是 1(打开)

我把它改成 0,问题就完全解决了:

后面再观测 cwnd,稳定在 1000 左右。

有了这个行为,我再去寻找这么做的原因就简单了。

RFC2414 里面提到:

TCP 需要在 3 种情况用到 slow start(从这个表述也可以看出,slow_start_after_idle 不是拥塞控制算法应该做的,拥塞控制算法要做的是实现 slow start,TCP 的实现是使用 slow start):

  1. 连接刚刚建立的时候 (Initial Window)
  2. 连接在 idle 一段时间之后,重新启动的时候 (Restart Window)
  3. 发生丢包的时候 (Loss Window)

那么为什么需要 (2) idle 后要 slow start 呢?我找到了 RFC 5681,有关 “Restarting Idle Connections“ 的部分,大意是:

拥塞控制算法使用收到的 ACK 来确认网络质量从而避免拥塞,但是在 idle 了一段时间之后,没有 ACK 在传输,拥塞控制算法所保存的状态可能已经不能反映此时的网络情况了,比如发送了一波数据,直到发送完成的时候网络都比较空闲,然后连接 idle 了 10s,又要开始发数据,此时网络恰好负载比较高,如果 TCP 使用 10s 之前的知识去重新开始发送数据的话,就会造成拥塞;另外,10s 之后即使网络负载没变,网络环境可能变了(路由表切换之类的?),同样会造成 10s 之前的知识已经不适用了。

所以,这个 RFC 里面定义:

在 RTO(Retransmission Timeouts) 时间内,如果发送端没有发送任何 segment 出去,那么下次发送数据的时候,cwnd 要降低到 RW(Restart Window, RW = min(IW,cwnd)).

到此,以上的行为就解释的通了。

那么解决方法呢?因为这个参数是 by network namespace 的,我们打算在高延迟的网络中对我们这个进程关闭这个参数。

关闭 tcp_slow_start_after_idle 的效果,可以看到在业务低峰,QPS 比较低的情况下,延迟有很大改善

另一个思路是,既然 TCP 连接在 idle 的时候会 reset,那么我一直在这个连接上发送数据,不让它达到 idle 的条件,那么自然就不会被 reset cwnd 了。

将测试代码稍微修改一下,打开一个线程,每 100ms (只要低于 RTT 就可以) 发送一个 byte:

然后用这个命令一直打印出来 cwnd 的参数:

while true; do ss -i | grep 10121 -A 1 | grep -Eo "cwnd:[0-9]+"; done

结果发现,cwnd 果然保持不变了。

可以看到 cwnd 一直保持在相同的数值,a 是正常数据,而 x 是无论如何每 100ms 发送一次的冗余数据。

如果无法修改系统参数的话(比如,同一个系统上运行了很多服务,不想去影响所有的服务),可以通过这种 keepalive 的方法来解决。代价就是需要稍微消耗一些带宽。

几个细节:

为什么我一开始在延迟低的物理网测试的时候没能复现呢?

其实也是有一样的问题的,只不过我上面那个 while 循环,有 sleep 0.1,因为环境的延迟太低,所以只是命令无法显示出来而已。cwnd 也会 reset to zero 的。

RFC 5681 提到:Van Jacobson 最初的提议是:当发送端在 RTO 时间内没有收到 segment,那么在下次发送数据的时候,cwnd 降低到 RW。这样是有问题的,比如,在 HTTP 长连接中,idle 一段时间之后,Server 端开始发送数据,本应该 slow start,这时候 client 突然又发送过来一个请求,会导致 server 端不再 slow start。故改成了目前这样:数据的发送端如果在 RTO 那没有发送过数据,要 slow start。

前面的文章中,TCP 拥塞控制对数据延迟的影响 我们使用长连接试图解决长肥管道慢启动延迟高的问题,是错误的。

这个参数目前看只是一个系统参数。应用不可以通过 setsockopt() 来修改,原因可以看这个讨论。本质上跟我们在 TCP 拥塞控制对数据延迟的影响 中讨论的一样,这个参数和网络环境有关,而不能让应用自己去设置。

 

TCP 拥塞控制对数据延迟的影响

这是上周在项目上遇到的一个问题,在内网把问题用英文分析了一遍,觉得挺有用的,所以在博客上打算再写一次。

问题是这样的:我们在当前的环境中,网络延迟 <1ms,服务的延迟是 2ms,现在要迁移到一个新的环境,新的环境网络自身延迟(来回的延迟,RTT,本文中谈到延迟都指的是 RTT 延迟)是 100ms,那么请问,服务的延迟应该是多少?

我们的预期是 102ms 左右,但是现实中,发现实际的延迟涨了不止 100ms,P99 到了 300ms 左右。

从日志中,发现有请求的延迟的确很高,但是模式就是 200ms, 300ms 甚至 400ms 左右,看起来是多花了几个 RTT。

接下来就根据日志去抓包,最后发现,时间花在了 TCP 本身的机制上面,这些高延迟的请求都发生在 TCP 创建连接之后。

首先是 TCP 创建连接的时间,TCP 创建连接需要三次握手,需要额外增加一个 RTT。为什么不是两个 RTT?因为过程是这样的:

即第三个包,在 A 发给 B 之后,A 就继续发送下面的数据了,所以可以认为这第三个包不会占用额外的时间。

这样的话,延迟会额外增加一个 RTT,加上本身数据传输的一个 RTT,那么,我们能观察到的最高的 RTT 应该是 2 个 RTT,即 200ms,那么为什么会看到 400ms 的请求呢?

从抓包分析看,我发现在建立 TCP 连接之后,客户端并不是将请求一股脑发送给服务端,而是只发送了一部分,等到接收到服务端的 ACK,然后继续在发送,这就造成了额外的 RTT。看到这里我恍然大悟,原来是 cwnd 造成的。

cwnd 如何分析,之前的博文中也提到过。简单来说,这是 TCP 层面的一个机制,为了避免网络赛车,在建立 TCP 连接之后,发送端并不知道这个网络到底能承受多大的流量,所以发送端会发送一部分数据,如果 OK,满满加大发送数据的量。这就是 TCP 的慢启动。

那么慢启动从多少开始呢?

Linux 中默认是 10.

也就是说,在小于 cwnd=10 * MSS=1448bytes = 14480bytes 数据的情况下,我们可以用 2 RTT 发送完毕数据。即 1 个 RTT 用于建立 TCP 连接,1个 RTT 用于发送数据。

下面这个抓包可以证明这一点,我在 100ms 的环境中,从一端发送了正好 14480 的数据,恰好是用了 200ms:

100ms 用于建立连接,100ms 用于发送数据

如果发送的数据小于 14480 bytes(大约是 14K),那么用的时间应该是一样的。

注意,图中虽然 TCP 在我手的时候,双方协商的 MSS 是 1460bytes,但是由于 TCP 的 Timestamps 会在 options 中占用 12 bytes,所以实际上发送的数据,payload 最大为 1448bytes. 在本文中,可以理解为实际的数据段的 maximum segment size 是 1448 bytes。

Timestamps 在 Options 中占用 12 bytes

但是,如果多了即使 1 byte,延迟也会增加一个 RTT,即需要 300ms。下面是发送 14481 bytes 的抓包情况:

多出来一个 100ms 用于传输这个额外的 byte

慢启动,顾名思义,只发生在启动阶段,如果第一波发出去的数据都能收到确认,那么证明网络的容量足够,可以一次性发送更多的数据,这时 cwnd 就会继续增大了(取决于具体拥塞控制的算法)。

这就是额外的延迟的来源了。回到我们的案例,这个用户的请求大约是 30KiB,响应也大约是 30KiB,而 cwnd 是双向的,即两端分别进行慢启动,所以,请求发送过来 +1 RTT,响应 +1 RTT,TCP 建立连接 +1 RTT,加上本身数据传输就有 1 RTT,总共 4RTT,就解释的通了。

解决办法也很简单,两个问题都可以使用 TCP 长连接来解决。

PS:其实,到这里读者应该发现,这个服务本身的延迟,在这种情况下,也是 4个 RTT,只不过网络环境 A 的延迟很小,在 1ms 左右,这样服务自己处理请求的延迟要远大于网络的延迟,1 个 RTT 和 4 个 RTT 从监控上几乎看不出区别。

PPS:其实,以上内容,比如 “慢启动,顾名思义,只发生在启动阶段“,以及 ”两个问题都可以使用 TCP 长连接来解决“ 的表述是不准确的,详见我们后面又遇到的一个问题:TCP 长连接 CWND reset 的问题分析

Initial CWND 如果修改的话也有办法。

这里的 thread 的讨论,有人提出了一种方法:大意是允许让应用程序通过 socket 参数来设置 CWND 的初始值:

setsockopt(fd, IPPROTO_TCP, TCP_CWND, &val, sizeof (val))

——然后就被骂了个狗血淋头。

Stephen Hemminger 说 IETF TCP 的家伙已经觉得 Linux 里面的很多东西会允许不安全的应用了。这么做只会证明他们的想法。这个 patch 需要做很多 researech 才考虑。

如果 misuse,比如,应用将这个值设置的很大,那么假设一种情况:网络发生拥堵了,这时候应用不知道网络的情况,如果建立连接的话,还是使用一个很大的 initcwnd 来启动,会加剧拥堵,情况会原来越坏,永远不会自动恢复。

David Miller 的观点是,应用不可能知道链路 (Route) 上的特点:

  1. initcwnd 是一个路由链路上的特点,不是 by application 决定的;
  2. 只有人才可能清楚整个链路的质量,所以这个选项只能由人 by route 设置。

所以现在只能 by route 设置。

我实验了一下,将 cwnd 设置为 40:

通过 ip route 命令修改

然后在实验,可以看到这时候,client 发送的时候,可以一次发送更多的数据了。


后记

现在看这个原因,如果懂一点 TCP,很快就明白其中的原理,很简单。

但是现实情况是,监控上只能看到 latency 升高了,但是看不出具体是哪一些请求造成的,只知道这个信息的话,那可能的原因就很多了。到这里,发现问题之后,一般就进入了扯皮的阶段:中间件的用户拿着监控(而不是具体的请求日志)去找平台,平台感觉是网络问题,将问题丢给网络团队,网络团队去检查他们自己的监控,说他们那边显示网络没有问题(网络层的延迟当然没有问题)。

如果要查到具体原因的话,需要:

  1. 先从日志中查找到具体的高延迟的请求。监控是用来发现问题的,而不是用来 debug 的;
  2. 从日志分析时间到底花在了哪一个阶段;
  3. 通过抓包,或者其他手段,验证步骤2 (这个过程略微复杂,因为要从众多连接和数据包中找到具体一个 TCP 的数据流)

我发现在大公司里面,这个问题往往牵扯了多个团队,大家在没有确认问题就出现在某一个团队负责的范围内的时候,就没有人去这么查。

我在排查的时候,还得到一些错误信息,比如开发者告诉我 TCP 连接的保持时间是 10min,然后我从日志看,1min 内连续的请求依然会有高延迟的请求,所以就觉得是 TCP 建立连接 overhead 之外的问题。最后抓包才发现明显的 SYN 阶段包,去和开发核对逻辑,才发现所谓的 10min 保持连接,只是在 Server 侧一段做的,Client 侧不关心这个时间会将 TCP 直接关掉。

幸好抓到的包不会骗人。

 

Golang 程序 crash 的时候自动 core dump

前段时间遇到一个问题,程序莫名其妙 crash 了,stack 也没看出什么端倪来。今天改了一个参数,让 golang 程序在崩溃的时候 core dump。

其实核心就是加一个环境变量就可以了,GOTRACEBACK=1. 但是还有一些其他跟系统相关的问题,这篇文章简单记录一下。

Golang 1.6 之后,这个环境的变量可选值有了一些变化,新的值如下:

  • GOTRACEBACK=none will suppress all tracebacks, you only get the panic message.
  • GOTRACEBACK=single is the new default behaviour that prints only the goroutine believed to have caused the panic.
  • GOTRACEBACK=all causes stack traces for all goroutines to be shown, but stack frames related to the runtime are suppressed.
  • GOTRACEBACK=system is the same as the previous value, but frames related to the runtime are also shown, this will reveal goroutines started by the runtime itself.
  • GOTRACEBACK=crash is unchanged from Go 1.5.

一些要注意的点:

首先,介绍下除了这个 GOTRACEBACK 参数,还有其他一些很有用的能控制 golang 运行时的环境变量,这篇文章总结的很好。

然后这个参数在 macOS 上是无效的,就不要在 MAC 上白费力气了。

Linux 上还受到 ulimit 的限制。可以用 ulimit -c 查看对 Core dump 的大小限制。如果是 0 是 dump 不出来了,也不建议设置成 ulimited。我改成了 50G。如果程序使用 systemd 启动的,可以设置 service unit 文件中的 LimitCORE= 参数,效果等同。

产生的 core dump 存放在哪里了呢?

可以通过这里查看:

这里定义了 core dump 文件的命名方式。

但是在 ubuntu 里面,会看到这样的输出:

意思是通过 pipe 定向到了 apport. apport 是 ubuntu 发行版选择使用的 core dump 管理服务。

默认情况下,用户程序是不会有 core dump 的。然后我们有两个解决办法:

  1. 关闭 apport,使用系统的 core dump 直接写在磁盘上
  2. 配置 apport,让它也写用户的 core dump 文件

第一种方法比较简单,直接修改上文中的 /proc/sys/kernel/core_pattern 文件即可:

注意这里有一个小小的问题要注意一下:这个配置是全局的,只有 root 账户才能编辑。如果在普通用户下执行 sudo echo "kernel.core_pattern=/tmp/%e.%t.%p.%s.core" > /proc/sys/kernel/core_pattern 是不行的,因为在这行命令中,echo 是用 sudo 执行的,但是重定向确实 shell (bash) 来完成的,重定向,即真正的写入工作,实际上没有在 root 下,所以你会得到错误:Permission denied, 或者 Destination /proc/sys/kernel not writable. 解决办法是用这个命令:sudo bash -c 'echo "kernel.core_pattern=/tmp/%e.%t.%p.%s.core" > /proc/sys/kernel/core_pattern'.

然后可以 disable apport:

 

第二种方法,首先要确保 apport 在运行。可以通过 systemctl status apport 查看。也可以看下 apport 日志:

触发一次 core dump,会看到:

意思是 core dump 不是来自于 ubuntu 打包的软件,忽略。

配置方法是,修改 ~/.config/apport/settings (如果没有,手动创建)文件,写入:

再触发一次 core dump,这次日志里就会有写入的信息了:

还要注意的是,这个文件不是 core dump 文件,而是 apport 打包的 debug 文件,可以使用 apport-unpack 解包:

解包出来的 CoreDump 就可以用 gdb 分析了。其他的文件记录了一些系统相关的信息。(感觉是 Ubuntu 用来让用户报告 bug 的)

 

最后,如果进程的 workdir 下没有生成 core dump 的话,可以看下是不是在 /var/lib/systemd/coredump/,网上说用 systemd 的系统会存放在这里,不过我没遇到。