EC2
+---------------+
| +---------+ |
| | | |
+-------> BACKEND | |
| | | | |
| | +---------+ |
| +---------------+
+------+ |
Public | | |
-------> ZUUL +--+
traffic | | | Kubernetes
+------+ | +-----------------------------+
| | +-------+ +---------+ |
| | | | xx | | |
+-------> NGINX +------> BACKEND | |
| | | xx | | |
| +-------+ +---------+ |
+-----------------------------+
问题看上去是后台的上游延迟(上图用xx表示)。当应用程序部署在EC2上时,响应时间大概20ms。在Kubernetes上则需要100~200ms。我们很快排除了运行时变更的影响。JVM版本是一致的。容器化的影响也被排除了,因为EC2上也是运行在容器里。也和压力无关,因为即使每秒只有1个请求仍然能看到很高的延时。也不是GC的影响。一个Kubernetes管理员问应用程序是否有外部的依赖,比如以前DNS解析曾经导致过类似的问题,这是目前为止最可能的猜想。猜想1:DNS解析
每次请求里,我们的应用程序会向AWS ElasticSearch实例(域名类似 elastic.spain.adevinta.com)发送1~3次请求。我们在容器内放置了一个shell脚本可以验证这个域名从DNS解析需要多长时间。容器内的DNS查询:
[root@be-851c76f696-alf8z /]# while true; do dig "elastic.spain.adevinta.com" | grep time; sleep 2; done
;; Query time: 22 msec
;; Query time: 22 msec
;; Query time: 29 msec
;; Query time: 21 msec
;; Query time: 28 msec
;; Query time: 43 msec
;; Query time: 39 msec
运行着对应相同用程序的EC2实例里的同样的查询:
bash-4.4# while true; do dig "elastic.spain.adevinta.com" | grep time; sleep 2; done
;; Query time: 77 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
;; Query time: 0 msec
大概30ms的解析时间,似乎我们的应用程序在和ElasticSearch通信时增加了DNS解析的额外消耗。但是这里有两点很奇怪:
在Kubernetes里已经有很多应用程序和AWS资源通信,但是并没有这个问题。
我们知道JVM实现了内存内的DNS缓存。查看这些镜像的配置,在 $JAVA_HOME/jre/lib/security/java.security里配置了TTL为 networkaddress.cache.ttl=10。JVM应该能够缓存10秒内的所有DNS查询。
34.55.5.111 elastic.spain.adevinta.com
这样容器可以立刻解析IP。我们确实观察到了延时的改善,但是离我们的最终目标还是很远。即使DNS解析足够快,但是真实原因还是没有找到。网络plumbing
我们决定在容器里执行 tcpdump,这样可以看到网络到底干了些什么。
[root@be-851c76f696-alf8z /]# tcpdump -leni any -w capture.pcap
然后发送了一些请求并且下载了capture文件( kubectl cpmy-service:/capture.pcap capture.pcap)在Wireshark[1]里查看。DNS查询看上去很正常(除了一些细节,之后会提到)但是我们的服务处理请求的时候很奇怪。下图是capture的截图,显示一个请求从开始到响应的全过程。
第一列是packet序号。我用不同的颜色标示不同的TCP流。绿色的流从packet 328开始,显示客户端(172.17.22.150)开启了容器(172.17.36.147)的TCP连接。最初的握手(328-330)之后,packet 331开始 HTTP GET/v1/..,这是对我们自己服务的入站请求。整个流程花了1ms。灰色流从packet 339开始,展示了我们的服务发送一个HTTP请求给Elasticsearch实例(这里看不到TCP握手过程因为它使用了一个已有的TCP连接)。这里花了18ms。至此都没有什么问题,所花的时间和预计差不多(~20-30ms)。但是在这两次交互之间,蓝色部分花了86ms。这里发生了什么?在packet 333, 我们的服务发送了HTTP GET到 /latest/meta-data/iam/security-credentials,之后,在同一个TCP连接里,另一个GET发送到 /latest/meta-data/iam/security-credentials/arn:..。我们发现每次请求里都会这样做。DNS解析在容器里确实有一点慢(解释很有意思,我会在另一篇文章里介绍)。但是高延迟的实际原因是每次请求里对AWS Instance Metadata的查询。猜想2:AWS调用
这两个endpoint都是AWS Instance Metadata API[2]的一部分。我们的微服务从Elasticsearch里读取时会用到这个服务。这两个调用都是基础的授权工作流。第一个请求里查询的endpoint得到和该实例相关联的IAM角色。
/ # curl http://169.254.169.254/latest/meta-data/iam/security-credentials/
arn:aws:iam::<account_id>:role/some_role
第二个请求查询第二个endpoint得到该实例的临时credential。
/ # curl http://169.254.169.254/latest/meta-data/iam/security-credentials/arn:aws:iam::<account_id>:role/some_role`
{
"Code" : "Success",
"LastUpdated" : "2012-04-26T16:39:16Z",
"Type" : "AWS-HMAC",
"AccessKeyId" : "ASIAIOSFODNN7EXAMPLE",
"SecretAccessKey" : "wJalrXUtnFEMI/K7MDENG/bPxRfiCYEXAMPLEKEY",
"Token" : "token",
"Expiration" : "2017-05-17T15:09:54Z"
}
客户端可以在短时间内使用它们,并且需要周期性地(在 Expiration之前)去获取新的credencial。模型很简单:AWS为了安全考虑经常轮询临时密钥,但是客户端可以将密钥缓存几分钟来弥补获得新credencial所带来的性能影响。AWS Java SDK应该处理这些,但是,因为某种原因,它没有这么做。在GitHub issue里搜索后找到了#1921[3],里面有我们需要的线索。AWS SDK在下面两种情况的某一种满足时就会刷新credential:
Expiration在 EXPIRATION_THRESHOLD内,硬编码为15分钟。
前一次刷新credential的尝试所花时间大于 REFRESH_THRESHOLD,硬编码为60分钟。
https://wiki.wireshark.org/FrontPage
https://docs.aws.amazon.com/AWSEC2/latest/UserGuide/iam-roles-for-amazon-ec2.html#instance-metadata-security-credentials
https://github.com/aws/aws-sdk-java/issues/1921
https://github.com/uswitch/kiam
https://github.com/aws/aws-sdk-java/issues/1893