thrift 大list序列化过慢引发的客户端耗时记录和服务端不一致问题

一、问题背景

最近在工作上遇到了一个问题，客户端说我们服务的返回长尾太长了，经常40+ms。找了一个trace发现，我们服务端记录这个trace从开始到返回，总共才花了6ms。多试了几个trace发现有同样的现象，这就很奇怪了。

二、问题分析

1. 请求链路

首先思考一下一个请求的整个链路都包含哪些阶段

如图所示，对于客户端来说，他们的耗时记录是在最上面两个过程中，但是服务端是最下面函数处理前后，两者差着序列化和tcp传输，所以猜测是不是这两个地方导致的问题。

2. tcp传输

我们的rpc框架用的是thrift 0.9.2，比较成熟了，所以优先考虑的是不是tcp传输过程中特别慢。如果是tcp的话最好的方法就是抓包了，在服务器上使用命令：

sudo tcpdump host 100.69.93.36 -i any -Xvv  -w dump.pcap

获取到超时的请求和返回，用本地wireshark的Flow Graph下面的tcp flows来查看tcp的过程：

第二部分，省略了中间一部分数据传输：

可以看到，虽然传输的报文段很多，开始直接达到了客户端告诉我们的最大窗口值，但是网络传输时花费的时间并不长。只有两个地方时间较长（图中红框中的），比较诡异，分别是

1. 服务端返回请求响应ACK之后，到第二个ACK过程(19ms)
2. FIN之前的ACK到FIN(74ms)
   分别分析，第一个情况其实就是服务端中函数处理时间，长点就长点吧。第二个是什么情况，花了这么久？我们知道FIN请求是在断开连接之后才会启动的，我们的例子中客户端是在请求服务端后立即就释放了，那么很有可能就是客户端在socket到反序列化过程中时间特别长。

2. 反序列化

我们用的是thrift，他的反序列化其实就是在recv_Func()中，截取一部分代码：

   if (ftype == ::apache::thrift::protocol::T_LIST) {
   
     {
   
       this->coords.clear();
       uint32_t _size0;
       ::apache::thrift::protocol::TType _etype3;
       xfer += iprot->readListBegin(_etype3, _size0);
       this->coords.