ning

hide [archives] [tags] [rss]

redis-slow-query-20140528

Permalink: 2014-05-29 22:38:30 by ning in redis tags: all

1   表现

昨天, 我们优化过之后的twemproxy终于全流量上线了, 这个上线是通过数据迁移的方式, 把老的单实例redis上的数据导到redis集群的方式完成的.

上线后, 发现切流量到集群后, 前端响应时间从7ms左右上升到15ms左右. 这和我们线下测试的结果严重不符.

为此, 给proxy增加了一条notice日志, 用于观察响应时间.

通过日志观察, 多数请求在proxy上看的响应时间都在1ms以下(从收到第一个包, 到最后响应发送完成):

$ tail -f log/nutcracker.log  | grep nc_request.c:59 | grep MGET
[Thu May 29 22:45:13 2014] nc_request.c:59 req 2794795960 done on c 160 req_time: 0.274 type: MGET narg: 2 mlen: 48 key0: ccccccc_5965730729490562984, done: 1, error:0
[Thu May 29 22:45:13 2014] nc_request.c:59 req 2794795741 done on c 238 req_time: 2.230 type: MGET narg: 3 mlen: 82 key0: ccccccc_8781424545207799628, done: 1, error:0
[Thu May 29 22:45:13 2014] nc_request.c:59 req 2794795846 done on c 965 req_time: 1.635 type: MGET narg: 9 mlen: 284 key0: ccccccc_8734244876870904753, done: 1, error:0

同时很多MGET, set, get等请求变得很慢. 而且, 慢请求总是集中出现.

2   分析

鉴于刚修改了proxy, 所以问题很可能出在 proxy上.

  1. 会不会是被某种慢请求拖累.

    proxy是单进程模型, 如果某个连接上的一个请求慢, 那么后续的请求都会受到影响. 这比较符合我们观察到的 慢请求集中出现的特点.

    在日志中, 观察一批慢请求中, 第一个拖慢大家的请求是什么, 并未发现明显特点.

  2. 会不会是因为客户端随机选择proxy不均匀? 这个问题之前出现过, 客户端使用time取模的方式选proxy, 于是同一秒内, 所有客户端都选择同一个proxy.

    针对今天的情况, 发现确实有不均匀的现象:

    $ tail -200000 log/nutcracker.log  | grep nc_request.c:59 | grep cou |  awk '{print $4}' | sort | uniq -c
    269 22:54:41
   2199 22:54:42
   1098 22:54:43
    578 22:54:44
   1448 22:54:45
   2720 22:54:46
    558 22:54:47
    507 22:54:48
   3084 22:54:49
   1677 22:54:50
    991 22:54:51
    396 22:54:52
    561 22:54:53
    423 22:54:54
    341 22:54:55
   1945 22:54:56
    727 22:54:57
    585 22:54:58
    453 22:54:59
    523 22:55:00
    520 22:55:01
    394 22:55:02
   2373 22:55:03
   3421 22:55:04
   3254 22:55:05
    595 22:55:06

    于是, 这个原因成了重点怀疑对象, 我甚至写了个脚本, 把每秒请求数和每秒慢请求化成图, 观察两者的相关性, 结果发现并无直接的相关.

    而且, 3000/s 的请求对proxy来说压力不算大, 看cpu也只占20%左右, 我们线下压力, cpu100%的时候大约能撑5w/s.

    到这时, 半天已然过去, 依然毫无头绪

  3. 第二天一大早, 开始着手从网络上去分析, 通过抓包, 观察客户端发给proxy, proxy再转给后端请求和响应, 这样可以确定是redis会给proxy慢呢, 还是proxy接收到响应后, 迟迟不回复给客户端.

    我先从proxy日志中找到一条慢日志, 然后到tcpdump的文件中通过key找, 找到:

    20:21:10.517897 IP 10.57.92.61.13766 > 10.57.85.40.2108: Flags [P.], ack 8852, win 4878, options [nop,nop,TS val 1266302405 ecr 1266305407], length 48
..A... ..+....E..d.i@.@..S
9\=
9U(5..<...x.........-.....
Kz=.KzI.*2^M
$4^M
mget^M
$27^M
ccccccc_1421521409803306481^M
20:21:10.518978 IP 10.57.92.61.13766 > 10.57.85.40.2108: Flags [P.], ack 8852, win 4878, options [nop,nop,TS val 1266302406 ecr 1266305408], length 48
..A... ..+....E..d.j@.@..R
9\=
9U(5..<.............-.....
Kz=.KzI.*2^M
$4^M
mget^M
$27^M
ccccccc_4472738999812611775^M
20:21:10.519474 IP 10.57.92.61.13766 > 10.57.85.40.2108: Flags [P.], ack 8852, win 4878, options [nop,nop,TS val 1266302406 ecr 1266305409], length 48
..A... ..+....E..d.k@.@..Q
9\=
9U(5..<.............-.....
Kz=.KzI.*2^M
$4^M
mget^M
$27^M
ccccccc_6172459129631416052^M
20:21:10.564537 IP 10.57.85.40.2108 > 10.57.92.61.13766: Flags [P.], ack 14768, win 4878, options [nop,nop,TS val 1266305454 ecr 1266302445], length 119
 ..+....A.....E...?Z@.=.8.
9U(
9\=.<5.............A......
KzI.Kz=.*1^M
$2^M
86^M      通过直接查询proxy, 发现ccccccc_1421521409803306481对应的value是86, 所以这里应该是前面第一个mget对应的response, 此时已经过去47ms.
*1^M
$-1^M
*1^M
$-1^M
*1^M
$3^M
287^M
*1^M
$-1^M
*1^M
$-1^M
:1^M

    我们发现这些请求的响应是一起回来的, 所以很有可能是因为后端hang住没有及时发回response.

    但是, 同一个tcp-stream上的前一个请求, 却是很快就响应的. 没有抓住有力证据.

    再用同样的方法, 就没有发现类似的case. 因为有的key很热, 没法定位到向后端转发的请求, 而且这基本靠肉眼, 太费劲了.

    还发现有一个case是proxy收到包之后过了5ms才转发给客户端的.

  4. 从前在http服务上也遇到不少慢请求的问题, 记得有一次把一小时的tcpdump用脚本分成了1,000,000 多个流, 然后对每个流里面相邻两个包的时间做度量, 如果超过xx ms, 就说明有慢请求. 翻了一下脚本, 是把 tcpdump 出来的一行一行的文件用正则式做分析, 每个流切到一个文件去:

    def deal(cap_file = '20110629-2000.all.txt'):
    all_line = int( system('cat %s | wc -l ' % cap_file))
    print all_line, 'lines'
    i = 0;
    for line in file(cap_file):
        if len(line) < 10: continue
        a = line.split(' ')[2].replace(':', '')
        b = line.split(' ')[4].replace(':', '')
        if (a.endswith('.80')):
            server = a
            client = b
            type = 'server->client'
        else:
            server = b
            client = a
            type = 'client->server'
        #print '##', client, server

        path = 'rst/' + client.replace('.', '/', 2)
        dirname = os.path.dirname(path)

        if not os.path.exists(dirname):
           os.makedirs(dirname)
        #print path
    #os.system('mkdir -p %s' % os.path.dirname(path))
        print >> file(path, 'a') , line,

        i += 1;
        if i % 10000 == 0:
            print i, 'lines finished'

    各种正则式... 无比费心.

    后来还用过一个tcpflow的工具, 可以帮助做这个切流的动作, 切完了之后再用一个脚本来分析. 重新下了个tcpfolw, 发现新版完全没法编译, 失去信心...

  5. 打算自己解pcap文件算了. 尝试了一下pypcap, 发现真是难用..

    于是乎, 自己python实现了一个pcap文件的解析库, 代码: py-pcap-parser

    然后利用这个库做分析, 分析代码:

    def dump():  #全量导出.
    pcap = PcapFile('a.pcap')
    cnt = 0
    for p in pcap.tcp_packets():
        cnt += 1
        if cnt % 100000 == 0:
            print '%d done' % cnt

        if not p.body:
            continue
        if filter(p):
            continue

        p.body = p.body.replace('\r\n', ' ')

        print TT('$ts $source:$source_port->$dest:$dest_port  # $body', vars(p))

def findslow(): 找到慢的req-response对.
    pcap = PcapFile('a.pcap')
    cnt = 0
    for p in pcap.tcp_packets():
        cnt += 1
        if cnt % 100000 == 0:
            print '%d done' % cnt

        if not p.body:
            continue
        if filter(p):
            continue

        p.body = p.body.replace('\r\n', ' ')
        #print TT('$ts $source:$source_port-$dest:$dest_port  # $body', vars(p))

        key = gen_key(p)
        if key in last_active:
            diff = p.ts - last_active[gen_key(p)]
            #print diff
            if diff > 0.03 and not isreq(p):
                print '===========', TT('$ts $source:$source_port->$dest:$dest_port  # $body', vars(last_pack[key]))
                print 'diff: %.3f' % diff,  TT('$ts $source:$source_port->$dest:$dest_port  # $body', vars(p))
        else:
            #print 'nodiff: ',  TT('$ts $source:$source_port-$dest:$dest_port  # $body', vars(p))
            pass

    分析结果, 在 findslow 输出里面, 慢请求一目了然:

    =========== 1401353285.95 10.57.27.53:56267-10.57.92.61:4101  # *4 $4 MGET $27 ccccccc_2111745379895909519 $27 ccccccc_4657069178215479939 $27 ccccccc_9137275223978700551
diff: 0.048 1401353285.99 10.57.92.61:4101-10.57.27.53:56267  # *3 $-1 $-1 $-1
=========== 1401353285.95 10.50.20.40:22796-10.57.92.61:4101  # *2 $4 MGET $27 ccccccc_5103351455575634229
diff: 0.047 1401353285.99 10.57.92.61:4101-10.50.20.40:22796  # *1 $-1
=========== 1401353285.96 10.38.12.42:42076-10.57.92.61:4101  # *2 $4 MGET $27 ccccccc_8030835834922447023
diff: 0.039 1401353285.99 10.57.92.61:4101-10.38.12.42:42076  # *1 $1 0

    上面这三个请求在不同时间点开始, 但是都是 1401353285.99 才完成.

    在把这个慢请求(ccccccc_2111745379895909519)放到全量的 dump 文件里面去找:

    1401353285.95 10.57.27.53:56267->10.57.92.61:4101  # *4 $4 MGET $27 ccccccc_2111745379895909519 $27 ccccccc_4657069178215479939 $27 ccccccc_9137275223978700551
1401353285.95 10.57.92.61:44471->10.42.194.43:2111  # *2 $4 mget $27 ccccccc_2111745379895909519
1401353285.96 10.57.92.61:44471->10.42.194.43:2111  # *2 $4 mget $27 ccccccc_8030835834922447023
1401353285.97 10.57.92.61:44471->10.42.194.43:2111  # *2 $4 mget $27 ccccccc_7981749853668200998
1401353285.98 10.57.92.61:44471->10.42.194.43:2111  # *2 $4 mget $27 ccccccc_8204274828390831284

    下面用 10.57.92.61:44471 去找, 我们又发现大量请求在同一时间点回来了:

    1401353285.99 10.42.194.43:2111->10.57.92.61:44471  # *1 $-1 *1 $-1 *1 $1 0 *1 $1 2 $303

    类似, 可以找到不少case, 说明确实是redis回的慢, 之前居然一直没有考虑过这个原因.

  6. 查redis为什么慢. 很快就定位到SLOWLOG. 发现很多redis每秒有几个SLOWLOG, 每次耗时20-40ms, 这和proxy上看到的数值很吻合:

    ./bin/deploy.py cluster1 mastercmd 'slowlog get 10'
...

1016892
1401377576
24807
HGETALL
xxxxxxxxxxxxxxxxxxxxxxx:1194330698
1016891
1401377576
24523
HGETALL
xxxxxxxxxxxxxxxxxxxxxxx:1194330698
1016890
1401377576
25147
HGETALL
xxxxxxxxxxxxxxxxxxxxxxx:1194330698

这些key很多都是2w+ hash

3   后续工作

  1. 把slowlog监控加入到 redis-mgr 常规监控
  2. 遇到响应时间问题, 优先排查SLOWLOG.
  3. 向业务限制HGETALL的使用

ps: HGETALL果然是个坑, 虽然早有耳闻, 一直未引起重视.

Comments