grpc 服务调用,首次建立连接后首次请求超时

Tags: grpc 

目录

现象

用户反映在kubernetes平台上使用自主开发的微服务系统(使用grpc调用),经常出现timeout的情况。

调查

在kubernets中创建两个pod,使用ab测试,没有发现异常:

在用户的两端的pod上进行抓包,分析发送端的报文发现一个异常情况:

536    2017-12-06 11:41:57.417197    192.168.252.78     192.168.219.243   TCP    153    50053 → 36128 [PSH, ACK] Seq=1619 Ack=4351 Win=328 Len=87 TSval=2015521395 TSecr=2074269577
537    2017-12-06 11:41:57.417413    192.168.219.243    192.168.252.78    TCP    66     36128 → 50053 [ACK] Seq=4351 Ack=1706 Win=259 Len=0 TSval=2074269582 TSecr=2015521395
661    2017-12-06 11:43:20.992070    192.168.219.243    192.168.252.78    TCP    895    36128 → 50053 [PSH, ACK] Seq=4351 Ack=1706 Win=259 Len=829 TSval=2074353157 TSecr=2015521395

192.168.252.78是grpc的调用的发起端,192.168.219.243是接收端。

重点是编号为537和661的报文,这两个报文都是接收端返回的,537是一个没有任何数据的ACK响应,661才是最终的数据回应,但是整整晚了1分23秒。

事后记录

调查过程实在是过于曲折,没能很好的记录中间过程,这里直接给出调查的结果。(获取的报文与上一节中的报文不是同一份)

通过在请求端和服务端抓取报文发现,在请求端首次建立GRPC连接后,请求端在2秒中等不到服务端的响应,于是发起了RST。

下面是在服务端抓取的报文:

64    2017-12-07 15:23:20.257002    192.168.252.78    192.168.38.233    HTTP2    1203   HEADERS, DATA
65    2017-12-07 15:23:20.257010    192.168.38.233    192.168.252.78    TCP      66     50069 → 58200 [ACK] Seq=50 Ack=1217 Win=31360 Len=0 TSval=3382334501 TSecr=2115204234
67    2017-12-07 15:23:22.256676    192.168.252.78    192.168.38.233    HTTP2    79     RST_STREAM
68    2017-12-07 15:23:22.296359    192.168.38.233    192.168.252.78    TCP      66     50069 → 58200 [ACK] Seq=50 Ack=1230 Win=31360 Len=0 TSval=3382336541 TSecr=2115206234

65号报文是client发出的,在20秒的时候发出,服务端立即做了ACK确认,但是客户端等待了两秒还没有收到后续的数据,于是在67个包进行了RST。

可以断定问题位于服务端,移交给微服务组的同学。


推荐阅读

Copyright @2011-2019 All rights reserved. 转载请添加原文连接,合作请加微信lijiaocn或者发送邮件: [email protected],备注网站合作

友情链接:  系统软件  程序语言  运营经验  水库文集  网络课程  微信网文  发现知识星球