一种定位服务超时的方法

背景:
服务器端的后端服务通常会基于某个框架(比如spring)开发业务逻辑,在进入某个服务的业务逻辑前通常由框架接收请求并进行参数封装,然后调用业务代码,如果直接在业务代码里通过打印日志记录请求进入时间,当请求量大到一定程度时打印出的时间是会产生误差的,因为服务本身由于高并发的性能瓶颈会出现卡顿,这样服务自身记录时间就会存在延迟,数据不准确导致无法作为问题定位的依据,这样就无法判断请求真正进入后端服务的时间。对于这种问题目前比较常见的排查方法主要是通过网卡抓包的形式,通过抓包工具(比如tcpdump)监听服务所在服务器的网卡,记录请求到达网卡的时间来确认请求是否发出。例如客户端A发出请求,当请求到达服务B时,抓包工具会记录请求到达服务B的时间,服务B继续请求服务C,此时抓包工具会继续记录服务C收到请求的时间,以及服务C返回请求后服务B收到请求返回的时间,最后根据对比服务B收到客户端A发出请求的时间,以及服务C收到服务B发出请求的时间,和服务B收到服务C返回请求的时间,通过三个时间可以确定以下3种情况:1、因为服务B发生了请求积压导致没有及时请求服务C导致超时;2、服务B发出了请求,并且请求到达了C,但是服务C没有来得及处理请求导致的超时;3、服务B请求了C,并且C在规定时间内返回了请求,但是B收到请求后,在后续处理结果数据超时,导致没有及时将结果返回给客户端导致超时。但是抓包方法效率非常低,因为抓包工具会记录经过网卡的所有数据,当请求量极大时,抓包工具抓到的数据包会非常大,此时需要解析数据包,通过对比每个请求发出的时间和返回的时间效率会很低,也极为不便。


通过在服务间增加代理服务器,由于代理服务器只做请求转发功能,没有其他业务逻辑,几乎可以认为不存在延迟,通过代理服务器记录的请求发出和返回时间,可以准确知道请求何时发出以及返回,能快速定位超时问题发生位置。


在一个应用系统中通常有多个服务,且服务之间存在依赖关系。

该发明整体结构如下图:首先客户端A发出请求,服务B接收到请求,此时B需要请求服务C,这时B不是直接请求C,而是请求nginx服务器,由nginx服务器将请求转发到C,C收到请求后执行业务逻辑,执行完毕返回结果数据给nginx,nginx服务器将数据重新返回给B,B拿到结果后再进行其他的逻辑处理,最后将结果返回给客户端A。


此时服务器记录了B发出请求的时间,可以根据服务B,nginx代理服务,服务C三方记录的请求到达和返回时间,通过脚本进行数据分析处理,可以快速定位每次请求的超时瓶颈属于哪种类型,找到问题原因,然后能针对性的对服务进行性能优化,提升服务质量,降低超时情况。

例如客户端A请求服务B时,希望服务B能在规定时间(假设1s)内返回,服务B又依赖了服务C,此时服务B调用服务C时期望服务C能在规定时间(假设100ms)内返回。当同一时刻客户端A大量请求服务B时,会出现超时返回的情况,此时超时原因可能有以下几种:

[if !supportLists]1. [endif]客户端A发出的请求在服务端B发生了积压,积压时间已经超过1s,此时1s后服务B再去请求服务C时,即使该请求到达了服务C,但是实际上该次请求已经超时。

[if !supportLists]2. [endif]客户端A发出的请求已经到达了服务端B,服务B继续请求服务C,服务C收到了请求,但是处理时间过长,导致请求返回B的时间已经超过了100ms,该次请求整体还是超时。

[if !supportLists]3. [endif]客户端A发出的请求已经到达了服务端B,服务B继续请求服务C,服务C收到了请求并在规定时间100ms内返回了请求,服务B收到了请求但是由于B还有业务处理逻辑,导致没有在整体时间1s内返回请求给客户端A,该次请求整体超时。

对于这3种情况,可以通过增设代理层(例如使用nginx服务),配置请求转发,并记录请求的到达时间和返回时间,可以快速定位超时原因是哪种。

对于这3种情况,分别绘制了流程图,可参见附图:


同时对nginx做如下配置:

log_format main ‘$http_requestid $remote_addr $upstream_addr [$time_local.$msec] ’$status $upstream_status $request_time $upstream_response_time’;

Server {

listen 8888;

location  / {

proxy_pass http://127.0.0.1:6666

}

解释:

time_local:是nginx收到请求的时间

request_time:是ngxin将请求转发给服务C的时间,可以近似认为是服务C收到请求的时间

upstream_response_time:是指从nginx向服务C建立连接开始到接收完数据然后关闭连接为止的时间

可以利用upstream_response_time来记录服务C响应所花费的时间,从日志时间开始,经过upstream_response_time,表明这是服务C响应的时间,再和服务B打印的耗时,做对比,来区分问题原因是哪种。

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

推荐阅读更多精彩内容