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的过程：

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

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

服务端返回请求响应ACK之后，到第二个ACK过程(19ms)
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.resize(_size0);uint32_t _i4;for (_i4 = 0; _i4 < _size0; ++_i4){xfer += this->coords[_i4].read(iprot);}xfer += iprot->readListEnd();}isset_coords = true;} else {xfer += iprot->skip(ftype);}

发现针对list的情况，他是for循环顺序解析的，每个coords又是一个结构体，会继续递归进行read。在这前后我们加一个时间戳打印函数，发现每次coord的解析都需要0.1ms！！那我们返回500个coord的时候，顺序反序列化岂不是就消耗了50ms。
客户端请求的时候是批量请求的，可以理解为二维数组，那么外围又是一个顺序解析的list，里面顺序解析coord，必然会很慢，至此原因就找到了。

3. 问题验证

既然是大list引发的问题，那么我们就先减少一下list的数量，发现果然耗时降到了20ms。

4. 更多疑问

为什么只有反序列化慢呢？
后面经过验证，发现之前序列化也很慢，只是上面的例子中可能是客户端性能较差（docker容器），导致反序列化慢的情况放大了。而且经过网上的benchmark测试，thrift序列化的时间更久。
为什么会慢？
我们使用的是TBinaryProtocol通过查看thrift源码，每次调用自带数据类型时，read的时候会调用：

template <class Transport_>
uint32_t TBinaryProtocolT<Transport_>::readI64(int64_t& i64) {union bytes {uint8_t b[8];int64_t all;} theBytes;this->trans_->readAll(theBytes.b, 8);i64 = (int64_t)ntohll(theBytes.all);return 8;
}

我们使用的是TFramedTransport，trans_->readAll()会调用下面的代码：

  /*** Shortcutted version of readAll.*/uint32_t readAll(uint8_t* buf, uint32_t len) {uint8_t* new_rBase = rBase_ + len;if (TDB_LIKELY(new_rBase <= rBound_)) {std::memcpy(buf, rBase_, len);rBase_ = new_rBase;return len;}return apache::thrift::transport::readAll(*this, buf, len);}
// return中readAll代码
/*** Helper template to hoist readAll implementation out of TTransport*/
template <class Transport_>
uint32_t readAll(Transport_ &trans, uint8_t* buf, uint32_t len) {uint32_t have = 0;uint32_t get = 0;while (have < len) {get = trans.read(buf+have, len-have);if (get <= 0) {throw TTransportException(TTransportException::END_OF_FILE,"No more data to read.");}have += get;}return have;
}return have;
}//trans.read函数
/*** Fast-path read.** When we have enough data buffered to fulfill the read, we can satisfy it* with a single memcpy, then adjust our internal pointers.  If the buffer* is empty, we call out to our slow path, implemented by a subclass.* This method is meant to eventually be nonvirtual and inlinable.*/uint32_t read(uint8_t* buf, uint32_t len) {uint8_t* new_rBase = rBase_ + len;if (TDB_LIKELY(new_rBase <= rBound_)) {std::memcpy(buf, rBase_, len);rBase_ = new_rBase;return len;}return readSlow(buf, len);}

可以看到，这里有个memcpy内存拷贝，外面还有一个while循环，应该就是这个地方比较耗时了。

三、解决方案

thrift协议我们没法直接改动，这样我们可以通过如下几种方案处理：

通过缩小返回的大小来处理，但是有的时候业务不允许。
客户端批量请求改为并行请求，不把时间耗费在list、map等数据结构的串行反序列化上。
既然是list和map引发的问题，那我们可以不用list和map，把list和map先使用pb等方式序列化成二进制流或者字符串，保证反序列化的时候不用串行遍历。