最近给服务增加了一个cache_put_latency指标，加了之后，吓了一跳。发现往memcached put一个10kb左右的数据，latency居然有7ms左右，难于理解，于是花了一些精力找原因。我分别写了一个shell和c++的测试程序。 1、shell脚本使用nc发送set命令。 #/bin/env ba
最近给服务增加了一个cache_put_latency指标，加了之后，吓了一跳。发现往memcached put一个10kb左右的数据，latency居然有7ms左右，难于理解，于是花了一些精力找原因。我分别写了一个shell和c++的测试程序。
1、shell脚本使用nc发送set命令。
#/bin/env bashlet s=1let i=0let len=8*1024while truedo if (( i >= $len )) then break fi str=${str}1 let i++donelet i=0begin_time=`date +%s`while truedo if (( i >= 1000 )) then break fi printf set $i 0 0 $len\r\n${str}\r\n | nc 10.234.4.24 11211 if [[ $? -eq 0 ]] then echo echo key: $i fi let i++doneend_time=`date +%s`let use_time=end_time-begin_timeecho set time consumed: $use_timelet i=0begin_time=`date +%s`while truedo if (( i >= 1000 )) then break fi printf get $i\r\n | nc 10.234.4.22 11211 > /dev/null 2>&1 let i++doneend_time=`date +%s`let use_time=end_time-begin_timeecho get time consumed: $use_time
2、c++程序则通过libmemcached set。
#include #include #include #include #include #include #include libmemcached/memcached.husing namespace std;uint32_t item_size = 0;uint32_t loop_num = 0;bool single_server = false;std::string local_ip;std::map servers;int64_t getcurrenttime(){ struct timeval tval; gettimeofday(&tval, null); return (tval.tv_sec * 1000000ll + tval.tv_usec);}memcached_st* mc_init(){ memcached_st * mc = memcached_create(null); if (mc == null) { cout ::iterator iter; for (iter = servers.begin(); iter != servers.end(); ++iter) { if (single_server && iter->first != local_ip) { continue; } memcached_return rc = memcached_server_add(mc, iter->first.c_str(), iter->second); if(rc != memcached_success) { cout first first 测试发现二者的结果是相背的。shell脚本set 1000次8kb的item，只要3s左右，平均需要3ms。而c++版本则需要39s左右，平均耗时39ms。照理说shell脚本需要不断连接服务器和启动nc进程，应该更慢才对。我用ltrace跟踪了一下，发现8kb的数据需要发送两次，两次write都是非常快的，但是等memcached返回时用了很多时间，主要的时间就耗费在这个地方。
23:32:37.069922 [0x401609]memcached_set(0x19076200, 0x7fffdad68560, 32, 0x1907a570, 8192 23:32:37.070034 [0x3f280c5f80]sys_write(3, set 29 0 6008192\r\naaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa..., 8196) = 8196 23:32:37.071657 [0x3f280c5f80]sys_write(3, aaaaaaaaaaaaaaa\r\n, 17) = 17 23:32:37.071741 [0x3f280c5f00]sys_read(3, stored\r\n, 8196) = 8 (39ms)
和剑豪讨论下之后，剑豪马上去grep了一把代码，发现原来libmemcached居然有memcached_max_buffer这样一个常量，其值为8196。并且它还没有对应的memcached_behavior_set函数。在memcached_constants.h中将其直接改成81960，然后就欣喜地发现cache_put_latency从7ms降低到1ms左右。
问题完美虽然地解决了，但是意犹未尽，于是想搞明白为什么会出现这种奇怪的现象。瓶颈貌似在服务器端，于是对memcached做了一些修改。在状态切换的时候加上一个精确到微秒的时间。
static int64_t getcurrenttime(){ struct timeval tval; gettimeofday(&tval, null); return (tval.tv_sec * 1000000ll + tval.tv_usec);}static void conn_set_state(conn *c, enum conn_states state) { assert(c != null); assert(state >= conn_listening && state state) { if (settings.verbose > 2) { fprintf(stderr, %d: going from %s to %s, time: %lu\n, c->sfd, state_text(c->state), state_text(state), getcurrenttime()); } c->state = state; if (state == conn_write || state == conn_mwrite) { memcached_process_command_end(c->sfd, c->wbuf, c->wbytes); } } }
从打印的时间戳可以看出来，时间主要花在conn_nread状态处理代码中。最后定位到第二次read花费的时间非常多。
15: going from conn_waiting to conn_read, time: 134846658444011815: going from conn_read to conn_parse_cmd, time: 1348466584440155 not found 98>15 stored15: going from conn_nread to conn_write, time: 1348466584480099(36ms)15: going from conn_write to conn_new_cmd, time: 134846658448014515: going from conn_new_cmd to conn_waiting, time: 1348466584480152
value的数据可能在conn_read中读完了，这个时候只需要memmove一下就好了。如果没有在conn_read状态中读完，那么就需要conn_nread自己来一次read了（因为套接字被设置成了异步，所以还可能需要多次read），关键就是这个read太慢了。
case conn_nread: if (c->rlbytes == 0) { complete_nread(c); break; } /* first check if we have leftovers in the conn_read buffer */ if (c->rbytes > 0) { int tocopy = c->rbytes > c->rlbytes ? c->rlbytes : c->rbytes; if (c->ritem != c->rcurr) { memmove(c->ritem, c->rcurr, tocopy); } c->ritem += tocopy; c->rlbytes -= tocopy; c->rcurr += tocopy; c->rbytes -= tocopy; if (c->rlbytes == 0) { break; } } /* now try reading from the socket */ res = read(c->sfd, c->ritem, c->rlbytes); if (res > 0) { pthread_mutex_lock(&c->thread->stats.mutex); c->thread->stats.bytes_read += res; pthread_mutex_unlock(&c->thread->stats.mutex); if (c->rcurr == c->ritem) { c->rcurr += res; } c->ritem += res; c->rlbytes -= res; break; }
折腾了好久，在libmemcached的io_flush函数前后也打了不少时间戳，发现libmemcached发送数据是非常快的。突然灵感闪现，我想起来了tcp_nodelay这个参数，于是在libmemcached memcached_connect.c文件中的set_socket_options函数中增加了这个参数（事实上set_socket_options函数里面可以设置tcp_nodelay，没有仔细看）。
int flag = 1; int error = setsockopt(ptr->fd, ipproto_tcp, tcp_nodelay, (char *)&flag, sizeof(flag) ); if (error == -1) { printf(couldn't setsockopt(tcp_nodelay)\n); exit(-1); }else { printf(set setsockopt(tcp_nodelay)\n); }
在不改memcached_max_buffer的情况下，现在set 100kb的item也是一瞬间的事情了。不过新的困惑又出现了，nagle算法什么情况会起作用呢？为什么第一个包没被缓存，第二个包一定会被缓存呢？
libmemcached发送一个set命令是分成三部分的，首先是header(set 0 0 600 8192\r\n，共18个字节)，然后是value(8192个字节)，最后是’\r\n’(两个字节)，一共是8212个字节。memcached在conn_read状态一共能读取2048+2048+4096+8196=16kb的数据，因此对于8kb的数据是完全可以在conn_read状态读完的。通过在conn_read状态处理的代码中增加下面的打印语句可以发现有些情况下，conn_read最后一次只读取了4个字节(正常情况应该是2048+2048+4096+20)，剩下的16个字节放到conn_nread中读了。
res = read(c->sfd, c->rbuf + c->rbytes, avail); if (res > 0) { char buf[10240] = {0}; sprintf(buf, %.*s, res, c->rbuf + c->rbytes); printf(avail=%d, read=%d, str=%s\n, avail, res, buf);
未设置tcp_nodelay选项时，使用netstat可以看到客户端socket的send-q一直会维持在8214和8215之间。
tcp 0 8215 10.232.42.91:59836 10.232.42.91:11211 established 25800/t
设置tcp_nodelay选项时，客户端socket的send-q就一直为0了。
tcp 0 0 10.232.42.91:59890 10.232.42.91:11211 established 26554/t.quick
原文地址：libmemcached的memcached_max_buffer问题, 感谢原作者分享。