背景说明

陌陌的微服务框架支持Redis协议调用方式， 在使用Redis协议调用MOA服务时， 每个请求会被包装为一个消息， 这个消息会用一个唯一ID来标识，ID是由机器名称+进程ID+消息产生的时间戳组成，当请求消息经过网络到达服务端应用后，MOA框架在处理消息前会先用当前时间减去消息的产生时间，如果差值大于100毫秒则会记录该请求到慢请求文件中。正常请求下该文件几乎不会产生数据，但是最近多名业务侧同学反馈慢请求文件数据较多，导致TP90数据飙高，希望帮忙排查原因。

排查过程

是否是容器问题？

陌陌的应用层全部跑在Docker容器上，为了排查容器自身因素，将该服务的部分实例迁到了VM上，对比发现VM上的实例基本上没有慢请求日志，所有基本确定该问题跟Docker容器相关。

网络不稳？

2018-12-18 12:23:40,822 REQUEST: Command [id=xxxxxxx-kube-node-web-php-

198861545107020.6728, action=/service/xxxx-action-service, source=127.0.0.1, thread=, params={args=[ap6896299708], m=getXxxRecReadNum}]? ### waitedTime: 103 ms

对比消息产生时间和服务端接收到数据包时间可知消息传递的网络耗时几乎可忽略，排除网络不稳定带来的影响。

网卡到socket读缓存区慢了？

通过上面tcpdump结果来说，数据从网卡到ReveiveQ再到用户态获取数据这一个过程也是及时的，为了再次验证这个结论，运维同学通过systemtap工具在tcp_v4_do_rcv调用时，将skb的内容打印出来，并将调用时间打印出来，通过比较系统调用时间和skb中的消息时间比对发现基本一致。?

//probe kernel.statement("tcp_rcv_established@net/ipv4/tcp_input.c:5256") {

probe kernel.function("tcp_v4_do_rcv").return {

	saddr = ip_ntop(@entry($sk->__sk_common->skc_daddr))

	daddr = ip_ntop(@entry($sk->__sk_common->skc_rcv_saddr)){

	if (saddr == "{source Addr}" && daddr == "{target Addr}")

		printf("taptime:%d, pid: %d,  %s:%d --> %s, %s\n", 

		gettimeofday_ms(),

		tid(),

		saddr,

		ntohs(@entry($sk->__sk_common->skc_dport)),

		daddr,

		__buffer_data(@entry($skb), 1)

	}

}