Alert 自动诊断系统的设计

在运维系统中,我认为 Alert 光发出来是不够的。每一个 Alert 发出来都需要处理,都要被解决。

我们现在设计的监控系统是这样的:

  1. Vmalert 是 alert rule evaluation 的组件,简单来说,它就是不断查询 TSDB 数据库中的数据,如果发现满足了 alert rule 的条件,就发送请求给 alertmanager;
  2. Alertmanager 会把 Alert 路由到正确的接受者,如果同一个 alert 被多个实例触发,它还会将他们聚合在一个 alert 中,只发送一条。此外,还有 Mute,高级 alert 抑制低级 alert,判断 alert 是否恢复的条件,等等功能。
  3. Alert reaction 是我写的一个系统,补充了开源监控系统中缺失的一部分:alert 的处理。这个系统在一次 PromCon 上分享过。Alertmanager 所有的 alert 会同时发送给 Alert reaction 一份,这个系统对于 Alertmanager 来说,就是一个普通的接受者。收到 alert 之后它会在自己的数据库中记录下来。

Alert reaction 系统能够提供的功能有:

  1. 对于所有触发过的 alert 进行统计,触发频率,应急事件,解决事件,等等,这些统计信息可以帮助我们优化 alert 触发的条件,让 alerting 效率更高;
  2. 保证所有的 alert 都有人在处理,设计了一个签到机制,alert 必须有人 ACK,如果没有 ACK 的话,过一段时间会 page 其他人;
  3. 有协同处理的功能,记录处理流程。比如可以在 Alert reaction 上面标记 alert,一键创建工单,评论等,所有时间会根据原先 alert 的路由策略发送更新消息。比如,Alertmanager 将 alert 发送到了 3 个群组,那么后续对于这个 alert 做出的更新会继续通知到这三个群组;
其中某一个 alert 的详情页面

最近发现这样还是不够的。很多 alert 需要人工处理,或者需要更加复杂的判断条件,仅仅用 metrics 无法表达出这样的 alert rule。比如,当发生 A 的时候,需要去检查 B,C,如果 B 和 C 都没有问题,则认为 A 有问题,如果其中一者有问题,我们认为不是 A 的问题。

即,我们需要用代码去定制 Alert rule,或者说需要用代码去处理发生的 alert。最近就写了这么一个框架。

框架的原理很简单:当 Alert Reaction 系统从 Alertmanager 收到 alert 的时候,将 alert 放到一个任务队列中,队列我选择的是用基于 Redis 做 broker 的 rq

任务队列本质上有两个:

  1. 第一个叫做 polyclinic (这在新加坡叫做综合医院,或者家庭门诊,人们需要看病的话首先要去这里咨询全科医生),polyclinic 会收到所有的 alert,然后匹配已注册的诊断程序(医生,doctor),如果匹配的话,将产生一个新的任务队列,放入 doctor queue
  2. Doctor queue 是真正执行诊断程序的 queue。没有什么逻辑,只是运行用户定义的函数
alert 的处理流程

对于用户来说,如果想要使用脚本来处理 alert 的话,只需要定义两个事情:

  1. 我的脚本能够处理哪一些 alert
  2. 如何处理(即代码逻辑)

我设计的目标是让用户需要写的代码足够少,上线速度足够快。因为这个编码的场景是需要不断调试,优化,来处理各种各样 alert 的场景。

我设计了一个装饰器,用户使用一个装饰器,只需要写一个函数,就可以了:

其中 diagnose 装饰器第一个参数就是如何 match alert,是和 PromQL 一样的 match 逻辑,不过只支持 equals match,不支持正则,not 等,因为用户函数的入参是携带了 alert 的原文的,所以如果要做更加复杂的 match 的话,可以在自己的代码中实现,如果不 match 在代码返回即可。post_comment 是框架所带的 SDK 的功能,可以回复评论到 Alert Reaction 系统上。

这个简单的实现带来了很多问题。

第一个问题是如何加载用户的代码。按照 Python 的 import 机制,如果这脚本文件从来没有被 import 过,那么不会被加载回 Python 的解释器的。一种方法是在 __init__ 里全 import 一遍,但是这样,每次添加新的诊断脚本,都需要记住要修改 import,否则,如果忘了的话,就比较难 debug 为什么我的脚本没有运行;另一种方法,就是我现在用的,worker 在启动的时候将用户脚本的目录全部扫描 import 一遍。感觉也不太优雅,也没有找到其他好的方法。

第二个问题是如何区分不同的诊断程序。比如各种 bot 都去给 alert 评论,怎么知道哪一条评论是谁发的。为了减少用户设置一个字段,这里直接用 function name 了,这个 decorator 的实现如下:

我是选择存储在 threadlocal 里面,然后用到的时候,比如在 post_comment 里,从 threadlocal 拿出来就可以了。有几个好处:

  1. 用户在调用 post_comment 的时候,不需要用户传递任何参数,在 post_comment 内部拿出来 threadlocal 就可以知道是谁想要发出评论;
  2. 在多线程环境下,比如多个 worker 同时执行,每一个都可以拿到正确的名字;

从上面的代码中可以看到还有一段 debug 相关的逻辑,这个很有意思,不是一个很容易理解的问题。一开始,我要让用户使用这个框架很方便地 debug,提供了几个功能:

  1. 可以针对构造的 alert 进行诊断测试,自己生成 alert 存在本地,然后一条命令就可以测试自己的程序;
  2. 可以直接针对线上的 alert 进行测试,直接一条命令就可以了

但是有一个问题,通过上面的架构描述,可以看到这个 alert 要被诊断,经过了很多系统,还有 job queue,用户本地测试可以跳过这些步骤,直接运行诊断程序就行。

那么为什么需要这段代码呢?

这里的区别就是我们放入 queue 的函数是被装饰的函数 real_func 还是原始函数 func. debug 环境没有经过 job queue,生产环境经过了 job queue。

如果有 job queue 在的话,中间存在一个序列化的过程。我们将任务放入 queue,实际上是在 Redis 里面存储了这个字符串。如果是被装饰的函数,rq 会将函数序列话成如下:

当 worker 拿到的话,反序列化出来是出错的。因为 worker 跑的时候装饰器已经运行完了,已经没有装饰器的上下文了。

如果 enqueue 的是原始函数,那么 worker 拿出来,其实运行的还是被装饰之后的函数,因为 worker 运行的时候,装饰器已经跑完了,所以原始函数实际上是运行完装饰器之后的函数了。(有点绕,注意这段代码在跑的时候,是装饰器的初始化阶段)

Debug 的时候没有 job queue,所以也就不存在序列化和反序列化,我们如果 enqueue 的是 func,那么实际跑的就是 func,因为这个场景没有 worker,没有人把装饰器都 evaluate 一遍再去跑实际的代码。如果是 func 的话,没有注入 threadlocal 的代码,后面获取 threadlocal 的时候就会报错。

除了这一个地方比较绕,其他的都比较直观。其他人写起来也比较好上手,关键是本地测试非常方便。

后记,我之前在蚂蚁金服的时候,也参与过类似的一个项目。回忆起来让人感慨万分。

这个项目有很多团队参与:老板设想的是所有 alert 1 分钟内发现,自动定位,自动恢复。分了三个组去完成这个目标。我们要对接监控系统发出来的消息,对接业务部门(我们的用户),对接上的成本难以想象的大,API 全没文档,数据格式乱七八糟,有一个叫 sunfire 的系统返回的监控数据是一个 json,其中有一个字段的 value 是 string,但是是一个 json 形式的 string,decode 之后里面还有一个字段是 json 形式的 string,我称之为 json in json in json,如果不反序列化,看到的都是 \\\\\\"\\\\"\\" 之类嵌套 N 层的转译符号,含义全靠猜。我们项目要想做出成果,一个关键就是搞大,所以就拉了很多人参与我们的项目,强制用户来这个诊断平台(那时候还叫中台)写规则。但是平台设计的糟糕,用户不会用,触发链条很长,测试成本很高,测试的方法就是在丁丁上喊其他组的人触发一下,效率很低。

为此搞了个闭关项目,还有誓师大会,做成了运动式的项目。实际上,第一个组胡乱配告警,配了上千条,平时没事也在一直发,每次故障总是能找出来几条 alert,可以说我们的发现率是 100% 了。做定位的,因为告警配置的垃圾所以我的工作相对也好做,绩效也不错。就是自愈比较难做。

前几天前同事戏称蚂蚁的项目是“年包”项目,指项目基本上只做一年。我那个时候做的项目一年之后也确实没了。

 

去爬黄山

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

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 直接关掉。

幸好抓到的包不会骗人。