Skip to content

Instantly share code, notes, and snippets.

@MOON-CLJ

MOON-CLJ/libmc_discuss_recv_error.md

Last active February 6, 2018 13:55
Show Gist options
  • Save MOON-CLJ/cd0e7b25fe40061a46a5c2ce84b67422 to your computer and use it in GitHub Desktop.
Save MOON-CLJ/cd0e7b25fe40061a46a5c2ce84b67422 to your computer and use it in GitHub Desktop.
Download ZIP
libmc discuss: 内部项目遇到的大量的recv error
Raw
libmc_discuss_recv_error.md

现象:

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引起的。如果处理得当， 并不会有明显的开销。

@MOON-CLJ
Copy link
Author

问题2的方案a更新，内部讨论的情况是方案a还会加上recv 0直接close(or markdead) 然后retry connect，用来保证recv 0这种server端graceful close connection情况下的不抛错，并且重试。之前描述的方案a只是这个处理的补充，相对来讲check interval 会设置的大一点。

cc @mckelvin @youngsofun @everpcpc

@MOON-CLJ
Copy link
Author

MOON-CLJ commented Feb 3, 2018 •
edited
Loading

问题2的方案更新，暂时只是我个人的意见。我尝试实现方案a 即markdead 并retry connect （douban/libmc@f9ed0d9 ）的过程中发现，如果是send了一部分的情况下，再recv 0的话，此时重连会带来一个棘手的问题是要把m_buffer_writer已经send出去的部分回滚。所以我有点倾向于方案b了。 @youngsofun @mckelvin

@youngsofun
Copy link

重连不处理类似的问题吗？

@MOON-CLJ
Copy link
Author

MOON-CLJ commented Feb 6, 2018

@youngsofun 比如https://github.com/douban/libmc/blob/master/src/Client.cpp#L193 是在ConnectionPool的dispatchIncrDecr里给m_buffer_writer takeBuffer (https://github.com/douban/libmc/blob/master/src/ConnectionPool.cpp#L335) 然后在waitPoll里收发，重连是在Connection这层。

@MOON-CLJ
Copy link
Author

MOON-CLJ commented Feb 6, 2018

@mckelvin 跟@youngsofun 讨论后，决定采用方案b单独处理这次的问题，即在waitPoll的最早阶段判断lastActive并及时重连。cc @everpcpc

@MOON-CLJ
Copy link
Author

MOON-CLJ commented Feb 6, 2018

如果是send了一部分的情况下，再recv 0的话，此时重连会带来一个棘手的问题是要把m_buffer_writer已经send出去的部分回滚。

经 @windreamer 的提醒，上面假设的这种情况理论上应该不会发生。如果send了部分了，connection则不idle了，server端不应该close连接。

所以退回到方案a。@mckelvin @youngsofun @everpcpc

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment