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

作者: 李佶澳   转载请保留:原文地址   发布时间:2017/12/06 13:38:42

现象

用户反映在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。

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

欢迎加微信,最好备注姓名和方向

QQ交流群

区块链实践互助QQ群:576555864

Kubernetes实践互助QQ群:947371129

Prometheus实践互助QQ群:952461804

API网关Kong实践互助QQ群:952503851

Ansible实践互助QQ群:955105412

Copyright @2011-2018 All rights reserved. 转载请添加原文连接,合作请加微信lijiaocn或者发送邮件: lijiaocn@foxmail.com,备注网站合作 友情链接: lijiaocn github.com