现象:
dae-go的一个项目elves，通过elves的sentry发现，通常（最近观察到的都是）在AM 1:00 到AM: 9:00 会出现大量的recv error，elves的开发者一直在追问是什么情况。
elves的用法如下
begin := time.Now()
if rated, err = mc.IncrUint64(key, 1); err != nil && err.Error() == LIBMC_CACHE_MISS_ERROR {
rated = 1
begin = time.Now()
err = mc.SetUint64(key, rated, int64(time.Hour/time.Second))
}
costTime := time.Now().Sub(begin)
if err != nil {
hostname, _ := os.Hostname()
scribe.Log(MC_ERROR_CATEGORY, fmt.Sprintf("hostname:%s, datetime:%s, cost time:%fs: %s", hostname, time.Now().Format(time.RFC3339), costTime.Seconds(), err.Error()))
onimaru.Report(onimaru.ERROR, err, "mc set error", nil)
}
return rated > _SPAM_THRESHOLD
debug 过程发现了一些问题，下面一一说明。 一个背景是dae-go里也有一层pool，pool里面是libmc的Client。
1，我在这个情况下增加了一行log记录recv error，比如
ssize_t nRecv = conn->recv();
if (nRecv == -1 || nRecv == 0) {
+ log_warn("[I: %p] recv_error, Connection(%p): %s, lastActive: %lu, nRecv: %zd",
+ this, conn, conn->name(), conn->getLastActive(), nRecv);
发现只要由于server迁移等情况造成配置更新，就会触发大量recv error 的log，并且就是dae-go的pool数乘以server数。即几乎所有连接都触发了recv error. 经过debug发现，dae-go的pool里给这个Client对应记录了version(为构建Client当时pool的version)，如果pool version增加，则pool里现有的这一批 Client全部销毁，销毁过程会调用Client quit。而由于libmc里的对quit的处理不当，因为server在收到quit之后，会close掉connection，而不会有任何返回。 libmc不应该期待在send quit cmd成功后期待能够recv return > 0。douban/libmc#73 这个pr对描述的问题做了处理。 但这只是libmc log里的recv error，和onimaru收集的接口返回的recv error是两回事。所以继续debug。
2, 我们通过log记录了某天晚上的现场，几乎就是以下log内容的重复。当晚没有mc server维护。（以下log内容不重要，只是列举出来）
2018-01-27 03:17:13.268180500 2018-01-27 03:17:13.267 WARN [85] [douban::mc::ConnectionPool::waitPoll@478] [E: None] [I: 0x7f1eb803d2c0] recv_error, Connection(0x7f1eb8084be8): mc-server648, nRecv: 0
2018-01-27 03:17:13.268221500 2018-01-27 03:17:13.267 WARN [85] [douban::mc::ConnectionPool::markDeadConn@645] [E: None] [I: 0x7f1eb803d2c0] markDeadConn(reason: recv_error), Connection(0x7f1eb8084be8): mc-server648
2018-01-27 03:17:13.268222500 2018-01-27 03:17:13.268 WARN [85] [douban::mc::Connection::markDead@198] [E: None] [I: 0x7f1eb8084be8] mc-server648 is dead(reason: recv_error, delay: 0), next check at 1516994233
2018-01-27 03:17:13.268247500 2018-01-27 03:17:13.268 INFO [85] [douban::mc::Client::incr@204] [I: 0x7f1eb803d2c0], err code recv_error
2018-01-27 03:42:57.078740500 2018-01-27 03:42:57.078 INFO [146] [douban::mc::Connection::tryReconnect@180] [I: 0x7f1eb8084be8] Connection mc-server648 is back to live
yangxiufeng和我通过log发现，几乎全是recv error。
chenlijun@dba1 ~ 2018-01-29 17:16:54 $ ack "still dead" /mfs/user/chenlijun/libmc_debug/debug_aaa | wc -l
4
chenlijun@dba1 ~ 2018-01-29 17:16:57 $ ack "back to live" /mfs/user/chenlijun/libmc_debug/debug_aaa | wc -l
10723
chenlijun@dba1 ~ 2018-01-29 17:17:02 $ ack "douban::mc::Client" /mfs/user/chenlijun/libmc_debug/debug_aaa | wc -l
10727
chenlijun@dba1 ~ 2018-01-29 17:17:05 $ ack "douban::mc::Client.*recv_error" /mfs/user/chenlijun/libmc_debug/debug_aaa | wc -l
10654
chenlijun@dba1 ~ 2018-01-29 17:17:25 $ ack "douban::mc::Client.*error" /mfs/user/chenlijun/libmc_debug/debug_aaa | wc -l
10727
并且back to live和上次出错间隔时间很长。比如还有这个log期间，都没有back to live的connection。 所以有以下对话
yangxiufeng [6:15 PM]
@chenlijun server 多长时间开始 关idle 连接？
chenlijun [6:15 PM]
@yangxiufeng 1小时
哦 你是说晚上qps低了 才会体现出问题？
有这个可能
yangxiufeng [6:16 PM]
嗯，client 每次访问 也记个 ts？ 收到 0 log 一下？
而且 golang 进程可能也不负载 均衡，比如 0x7f1cd4000a50 一直没有 back to alive
incr 每次搞一个，很可能有的conn比较空闲 (edited)
chenlijun [6:18 PM]
@yangxiufeng okay 我觉得你这个假设摸到点了 我想想怎么验证
@yangxiufeng 就你的方案 直接每个conn 记一个last_active 然后recv 0的时候带上这个last_active ts
问题回溯
-
memcached在 https://github.com/memcached/memcached/wiki/ReleaseNotes1427#new-features 这版引入了idle_timeout， 由我在内部memcached版本的一次升级中生效了，我们能够通过指标发现，能够有效的踢掉一些连接，对降低memcached的连接数有好处。
-
dae-go elves应用的的pool白天并发高到能够涨到250+，但是缩小的特别慢。简化问题，假设凌晨还是250+的CLient在dae-go的pool里面， 后端mc server一共330个。elves的用法如上所以就是incr or set单个key，所以当凌晨qps处于很低的水平的时候，极有可能出现某个Client里的connection 一个小时都没有request的情况，等过了一个小时，memcached kick掉这个connection，又来了request的话，就会立即碰上recv error。
问题验证步骤
chenlijun@dba1 ~/go/src/tmp 2018-01-30 11:37:10 $ cat main1.go [5/49734]
package main
import "fmt"
import "time"
import "github.com/douban/libmc/golibmc"
func main() {
servers := []string{
"redis00:11211",
"redis01:11211",
}
mc := golibmc.SimpleNew(servers)
mc2 := golibmc.SimpleNew(servers)
incr := func (c *golibmc.Client, key string) {
for i := 0; i < 3; i++ {
if _, err := c.Incr(key, 1); err != nil {
fmt.Println(err)
if (err == golibmc.ErrCacheMiss) {
item := &golibmc.Item{
Key: key,
Value: []byte("0"),
}
c.Set(item)
}
time.Sleep(15 * time.Second)
}
time.Sleep(15 * time.Second)
}
}
go incr(mc, "foo")
go incr(mc2, "foo2")
select{}
}
chenlijun@redis00 ~ $ memcached -o idle_timeout=10
chenlijun@redis01 ~ $ memcached -o idle_timeout=10
临时的代码的修改可以重点看这两个commit https://github.com/douban/libmc/pull/72/commits/42dc613b000165a6eae0951cac147ca19ea885fc https://github.com/douban/libmc/pull/72/commits/8203d42506745ac516754a80e29298f5fc1a03bf
有如下输出
2018-01-30 11:34:44.279 DEBUG [13574] [douban::mc::Connection::addRequestKey@241] [E: None] [I: 0x7f0814000b48] redis00:11211 add request key: foo
2018-01-30 11:34:44.279 DEBUG [13574] [douban::mc::Connection::send@277] [E: None] [I: 0x7f0814000b48] redis00:11211 sendmsg(12)
2018-01-30 11:34:44.279 DEBUG [13577] [douban::mc::Connection::addRequestKey@241] [E: None] [I: 0xdcaa98] redis01:11211 add request key: foo2
2018-01-30 11:34:44.279 DEBUG [13574] [douban::mc::Connection::recv@296] [E: None] [I: 0x7f0814000b48] redis00:11211 recv(0)
2018-01-30 11:34:44.279 WARN [13574] [douban::mc::ConnectionPool::waitPoll@479] [E: None] [I: 0x7f0814000a20] recv_error, Connection(0x7f0814000b48): redis00:11211, lastActive: 15$
7283284, nRecv: 0
2018-01-30 11:34:44.279 WARN [13574] [douban::mc::ConnectionPool::markDeadConn@646] [E: None] [I: 0x7f0814000a20] markDeadConn(reason: recv_error), Connection(0x7f0814000b48): red$
s00:11211
2018-01-30 11:34:44.279 DEBUG [13577] [douban::mc::Connection::send@277] [E: None] [I: 0xdcaa98] redis01:11211 sendmsg(13)
2018-01-30 11:34:44.279 DEBUG [13577] [douban::mc::Connection::recv@296] [E: None] [I: 0xdcaa98] redis01:11211 recv(0)
2018-01-30 11:34:44.279 WARN [13574] [douban::mc::Connection::markDead@219] [E: None] [I: 0x7f0814000b48] redis00:11211 is dead(reason: recv_error, delay: 0), next check at 151728$
284
2018-01-30 11:34:44.279 WARN [13577] [douban::mc::ConnectionPool::waitPoll@479] [E: None] [I: 0xdca040] recv_error, Connection(0xdcaa98): redis01:11211, lastActive: 1517283284, nR$
cv: 0
2018-01-30 11:34:44.279 DEBUG [13574] [douban::mc::Connection::markDead@225] [E: None] [I: 0x7f0814000b48] redis00:11211 first request key: foo
2018-01-30 11:34:44.279 WARN [13577] [douban::mc::ConnectionPool::markDeadConn@646] [E: None] [I: 0xdca040] markDeadConn(reason: recv_error), Connection(0xdcaa98): redis01:11211
2018-01-30 11:34:44.279 INFO [13574] [douban::mc::Client::incr@204] [I: 0x7f0814000a20], err code recv_error
2018-01-30 11:34:44.279 WARN [13577] [douban::mc::Connection::markDead@219] [E: None] [I: 0xdcaa98] redis01:11211 is dead(reason: recv_error, delay: 0), next check at 1517283284
libmc: network error(recv_error)
2018-01-30 11:34:44.279 DEBUG [13577] [douban::mc::Connection::markDead@225] [E: None] [I: 0xdcaa98] redis01:11211 first request key: foo2
2018-01-30 11:34:44.279 INFO [13577] [douban::mc::Client::incr@204] [I: 0xdca040], err code recv_error
libmc: network error(recv_error)
证实了以上大段内容描述的假设，并且这个问题是通用场景，而不仅仅是dae-go elves用法的问题，需要在libmc做处理。（线上的elves的情况将很快进行，但是要等晚上才有可能复现）
3, 还有一个顺带发现的问题是，在2中最后这段log可以发现一个问题，即在memcached idle kick的情况下，sendmsg还是能够成功发出去12bytes，之后recv return 0。
内部讨论认为这个代码处理send和recv的顺序不当，认为推荐的做法应该是poll同时听POLLIN | POLLOUT，先处理recv后处理send，这种recv出错的情况下及时处理。 https://github.com/douban/libmc/pull/72/commits/1cd71dbc1c0e5ef65f153359de05f8e96e783fe2 https://github.com/douban/libmc/pull/72/commits/2497900bfa7c7fe79d3d0c7e09543711427c5e49 这两个commit分别做了处理。
所以关于问题2，3，希望听下panmiaocai的意见。
希望沟通的是， 1，问题3的处理方式是否有疑问？ 2，问题2,我们目前有两个想法，a,目前poll的时候只带上了有读有写的需求的socket fd，可能不够，考虑通过一定的轮询策略在request的路径中带上idle的fd去poll POLLIN events， 如果发现有revents里有POLLIN但是recv return 0则markdead主动清理半开连接。保证一段时间内，所以的fd都被poll过。b，消极的处理半开连接，记录每个conn的上次成功 send or recv的时间为last_active，每次request的时候，检查last_active到现在为止已经超过了idle_timeout，则直接close并retryConnect，会引入新的idle_timeout配置项， 对应memcached server会设置的idle timeout。即如果server端用了idle_timeout，建议client也配置这个新的idle_timeout option。
两种方式目前讨论的结果是，a方案的倾向更高一些。理由是，a方案会更及时的清理半开连接，半开连接不一定仅仅只是由server idle kick引起的。如果处理得当， 并不会有明显的开销。
问题2的方案更新，暂时只是我个人的意见。我尝试实现方案a 即markdead 并retry connect （douban/libmc@f9ed0d9 ）的过程中发现，如果是send了一部分的情况下，再recv 0的话，此时重连会带来一个棘手的问题是要把m_buffer_writer已经send出去的部分回滚。所以我有点倾向于方案b了。 @youngsofun @mckelvin