【tcp】RT 过长,排查思路

大多数人应该听过一道经典的面试题:请详细地说出从浏览器地址栏输入 url 到最终呈现出结果的过程,越详细越好,为什么面试官这么喜欢问这道题呢,因为这个题涉及的面非常广,知识点非常多,如果你能完全吃透,非常有助于排查一些疑难杂症。

今天我要分享的这个 case 就是个典型,废话不多说,进入正题。

前端同学发现新开发的项目接口有 1/3 概率出现 RTT(请求往返时间)大于 3 s 的情况,以登录接口为例,Chrome 请求所花时间如下:

image

正常的 RTT 在几十 ms 左右,所以 3s 这个时延肯定不正常,于是着手排查,由于每个接口都可能超过 3s,所以下文皆以登录接口分析为例,因为登录接口逻辑相对比较简单。

  1. 排除浏览器本身的问题

估计大家看到这种问题马上就断定是 server 的问题,立马开始着手排查 server 的问题,不急,我们要先把浏览器本身可能导致请求缓慢的问题给排除了,浏览器本身可能因为「请求最大并发数量限制」,「更高优先级的请求插队,低优先级的任务被延后」等原因导致请求缓慢

为了排除浏览器本身造成的网络请求过慢,我们最好找一个其它的浏览器比如 Safari 或者终端 curl 请求来再重试下这个请求,看下请求是否依然缓慢,这里我两个方法都试了,用 Safari 也重现了 RTT 大于 3s 的情况。

用 curl 在终端请求也发现了 RTT 大于 3s 的情况,如何使用 curl 请求呢,这里提醒一下,大家千万不要傻傻地去构建一个 curl 请求,浏览器的网络请求本身可以导出成 curl 的形式的,在「network」中点击网络请求,选中「Copy as cURL」,就可获取此请求的 curl 表示方式

image

获得 curl 请求后,对此请求稍加改造,加上如下 -o,-s, -w 选项

$ curl -o /dev/null -s -w  \
"time_connect: %{time_connect} \n \
 time_starttransfer: %{time_starttransfer} \n \
 time_nslookup:%{time_namelookup} \n \
time_total: %{time_total} \n" \
https://www.example.com

这里对几个参数简要作下说明:
-o /dev/null 屏蔽原有输出信息,-s 静默模式,不输出任何东西,-w %{http_code} 控制额外输出。

请求后会出现类似以下的结果

time_connect: 0.045897
time_starttransfer: 3.064762
time_nslookup:0.004328
time_total: 3.064777

前面几个参数就不多做说明了,一般我们只要关心最后一个 time_total 参数即可,表示请求花费的全部时间。

从流量的流转路径着手了,客户端发出请求要经过哪些流程才能到达后端服务?

image.png

可以看到请求需要经过反向代理层,接入层后才能到达我们的站点层(即我们的 Spring MVC 服务),也就是说从「反向代理层到接入层」及「接入层到站点层」都可能导致请求缓慢,于是我把我用 arthas trace 执行的结果(MVC 服务执行时间 80ms 左右)与前端请求有 1/3 的概率超过 3s 的结论告诉了运维,让他们排查一下从反向代理层到站点层这中间是否有啥问题,不一会儿果然查出了问题。

结论是这样的:本来 MVC 服务的机器有三台,后来缩容了一台,变成了两台,但接入层 kongfu 依然持有这台被缩容的机器 ip,没有将其踢掉,所以前端流量打进来后,由于接入层的负载均衡策略,请求是有 1/3 的概率打到这台下线机器的 ip 上的,由于这个 ip 对应的机器无法响应这个请求,等到超时后,kongfu 会重试把这个请求打到另外正常的两台机器中的任意一台,也就是说请求 3s 中的大部分时间花在了等待那台不正常的 ip 机器响应上了。

image.png

有人可能会问,机器被踢掉了,接入层 kongfu 应该是能检测其下线的吧,怎么还会给这台下线的机器发请求呢?

是的,kongfu 会通过端口检测来检测机器是否存活的,但问题是,这台被缩容的机器虽然被回收了,但它的 ip 也是可以重新被分配给其他机器的,这种情况下 kongfu 通过端口检测就会认为它持有的 ip 对应的机器是存活的,而这台被分配此 ip 的机器又刚好不是 Spring MVC 服务,那正常 MVC 请求打给它的话,它就无法处理了,只能等到请求超时再由 kongfu 重试转发给正常的机器。

有人可能会好奇,运维是怎么查出来的呢,通过 「curl -I www.example」的形式可以输出开头信息,然后加上 -b 选项可以带上 cookie,我们的接入层如果发现请求里带有某些特殊的 cookie 会返回一个名为「X-KF-Via」的头字段,如下:

X-KF-Via: agw(bip=10.65.x.1:8001,10.65.x.2:8001;b=mvc_service)

这个头字段表示,请求 mvc_service 服务总共请求了两台机器,第一台 10.65.x.1 未成功后,再接着重试 10.65.x.2:8001,所以由此可以排查出 10.65.x.1 这台机器有问题,所以你看熟悉系统架构有多重要,如果我早知道有这么一个选项,就可以一步到位排查出此问题了.

知道了问题所在,处理方案就很简单了,直接把这台有问题的机器从 kongfu 摘掉就行了!

排查的思路其实相对比较清晰,但一定要对请求的整个流转流程有一个比较清醒的认识,这样才能快速判断出问题所在,现在再回头看下开头的那道经典面试题「请详细地说出从浏览器地址栏输入 url 到最终呈现出结果的过程,越详细越好」,相信你会颇有感触,这道面试题如果你对请求流转的每个点都吃透得话,将极大地提升你排查解决问题的能力,举个例子,之前就有人反馈这样的一个问题:

在做 Server 压力测试时发现,客户端给服务器不断发请求,并接受服务器端的响应。
发现接收服务器响应的过程中,会出现 recv 服务器端响应,阻塞 40ms 的情况,但是查看 server 端日志,Server 都在 2ms 内将请求处理完成,并给客户端响应

如果你了解 TCP,就知道它是由于 TCP 的延迟确认机制和 Nagle 算法及拥塞控制导致的,自然而然就会朝着这个方向 去解决了,比如打开 TCP_NODELAY 选项等。

参考

RT 过长,排查思路
https://bestxf.blog.csdn.net/article/details/118193092

记录线上RT规律性增长问题排查
//www.greatytc.com/p/0c0e5c438116

浏览器、 postman操作和curl命令互转
//www.greatytc.com/p/a6310e0fd290

用curl查看http请求各阶段响应时间
//www.greatytc.com/p/1f6e21e75841

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
平台声明:文章内容(如有图片或视频亦包括在内)由作者上传并发布,文章内容仅代表作者本人观点,简书系信息发布平台,仅提供信息存储服务。
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 230,002评论 6 542
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 99,400评论 3 429
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 178,136评论 0 383
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 63,714评论 1 317
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 72,452评论 6 412
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 55,818评论 1 328
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 43,812评论 3 446
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 42,997评论 0 290
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 49,552评论 1 335
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 41,292评论 3 358
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 43,510评论 1 374
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 39,035评论 5 363
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 44,721评论 3 348
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 35,121评论 0 28
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 36,429评论 1 294
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 52,235评论 3 398
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 48,480评论 2 379

推荐阅读更多精彩内容