目录
在排查redis性能问题时,从slowlog中找执行缓慢的命令进行优化是一种常规手段。redis slowlog被设计成内存中一个先进先出的队列结构,一旦容量被填满,新的条目就会挤出旧条目。特别是在慢日志较多的情况下,有些问题命令很快就会被刷新出slowlog,从而很难跟踪到。
为了解决历史慢日志跟踪问题,需要将redis slowlog定期转储到其它存储介质,如磁盘文件或MySQL数据库等。本文介绍使用shell脚本将slowlog转储到普通文本文件的设计实现。这个方案的特点是简单直接,无需其它语言或环境支持,只要在Linux上编写几行简单的shell脚本即可。
redis的slowlog是redis用于记录记录慢查询执行时间的日志系统。由于slowlog只保存在内存中,因此slowlog的效率很高,完全不用担心会影响到redis的性能。slowlog是redis从2.2.12版本引入的一条命令。
slowlog有两个配置参数:
可以在redis配置文件中设置slowlog参数,也可以使用config set命令动态进行设置。 slowlog命令用于查看慢日志信息:
# 查看slowlog总条数
127.0.0.1:20003> slowlog len
(integer) 128
127.0.0.1:20003>
# 查看slowlog
127.0.0.1:20003> slowlog get
1) 1) (integer) 89161
2) (integer) 1541121851
3) (integer) 20773
4) 1) "DEL"
2) "vvmusiclive_kroom_receive_k_gift_detail_list_908843175"
2) 1) (integer) 89160
2) (integer) 1541121711
3) (integer) 137653
4) 1) "COMMAND"
...
9) 1) (integer) 89153
2) (integer) 1541121481
3) (integer) 75091
4) 1) "COMMAND"
10) 1) (integer) 89152
2) (integer) 1541121371
3) (integer) 51331
4) 1) "COMMAND"
# 获取指定的条数可以使用SLOWLOG GET N命令
slowlog get 100
慢日志输出信息中最左列表示条目编号。每条慢日志由4项组成:1)是系统中的唯一ID号;2)是执行query的UNIX时间戳;3)是以微秒表示的query执行时间;4)是执行的命令。
slowlog的输出格式是固定的,因此可以定期执行slowlog get命令,将输出用追加方式重定向到磁盘文件。这样就解决了转储的问题,看似毫无难度。但问题并没有这么简单,我们还有以下几个问题需要解决:
redis-cli -p 20001 --no-raw slowlog get 128 |
gawk '{ if($0~/1\) \(integer\)/) {$1="";sub("^ *","");} else if($0~/2\) \(integer\)/) {gsub($3,strftime("%Y-%m-%d %H:%M:%S",$3));sub("^ *","");} else if($0~/3\) \(integer\)/) {sub("^ *","");} else if ($0~/4\) +1\)/) {gsub(/4\)/," ",$0);} {print $0}}' >> tmpfile.txt
说明:
1) (integer) 89218
2) (integer) 2018-11-02 10:10:00
3) (integer) 10519
1) "SADD"
2) "vvmusiclive_kroom_receive_k_gift_user_list"
3) "925826217"
4) "929306725"
5) "934086121"
6) "916089563"
7) "914163795"
8) "912578737"
9) "920874412"
10) "907827537"
11) "931068540"
12) "938706194"
13) "927533508"
14) "921846404"
15) "912687098"
16) "917264259"
17) "930628034"
18) "922576934"
19) "920568873"
20) "935731276"
21) "923170841"
22) "923189677"
23) "918620435"
24) "913823655"
25) "914592705"
26) "927324056"
27) "917882023"
28) "911605787"
29) "916684087"
30) "938970157"
31) "928144602"
32) "... (28095 more arguments)"
1) (integer) 89217
2) (integer) 2018-11-02 10:10:00
3) (integer) 14067
1) "DEL"
2) "vvmusiclive_kroom_receive_k_gift_user_list"
1) (integer) 89215
2) (integer) 2018-11-02 10:09:13
3) (integer) 14687
1) "HSET"
2) "kroom_gift_msg_hash"
3) "103.244.233.181_16287_331568_6000236_925076681_916572144_1541124553684"
4) "{\"roomServerIp\":\"114.112.77.220\",\"r_id\":916572144,\"receiveTicket\":2,\"dalIp\":\"103.244.233.181\",\"liveId\":331568,\"diamondPrice\":2,\"... (169 more bytes)"
1) (integer) 89214
2) (integer) 2018-11-02 10:07:28
3) (integer) 31447
1) "DEL"
2) "f_room_no_recommand_family_schedule_key1541123507699"
1) (integer) 89213
2) (integer) 2018-11-02 10:07:21
3) (integer) 111291
1) "COMMAND"
...
每次执行该命令都会将当前的slowlog格式化后追加到指定文件中。
前一步处理只是追加慢日志记录并格式化存储到文件中。如前所述,多次get到的条目需要做去重处理。每个慢日志条目由多行组成,其中前三行固定格式,但命令的行数是不定的。shell在处理文本文件时,一般都是按某些条件逐行去重,面对这种多行整体去重的场景,很自然想到行转列,将每个条目的多行转换成一行,然后在整行去重就容易了。去重后,再将每个条目的单行转成原始的多行格式化显示。完成这些工作的命令如下:
gawk '/^1\)/{print s;s=""};{ s=(s" "$0)};END{print s } ' tmpfile.txt | sort | uniq |
sed 's/ /\n /g' | gawk '/^ 1\) \(integer\)/{rc =rc+1;rowdata=rc") \t" $1" "$2" "$3"\n\t"$4" "$5" "$6" "$7"\n\t"$8" "$9" "$10;print rowdata};/^ /{print "\t"$0}' > resultfile
说明:
1) (integer) 89209 2) (integer) 2018-11-02 10:03:33 3) (integer) 48990
1) "ZADD"
2) "f_room_no_recommand_family_schedule_key1541124213383"
3) "0.0"
4) "1240"
5) "0.0"
6) "1396"
7) "450.0"
8) "1179"
9) "0.0"
10) "1465"
11) "0.0"
12) "1305"
13) "960.0"
14) "1138"
15) "0.0"
16) "1452"
17) "0.0"
18) "35274"
19) "0.0"
20) "1127"
21) "0.0"
22) "46632"
23) "0.0"
24) "1217"
25) "0.0"
26) "1297"
27) "0.0"
28) "1325"
29) "0.0"
30) "1185"
31) "0.0"
32) "... (1347 more arguments)"
1) (integer) 89210 2) (integer) 2018-11-02 10:03:40 3) (integer) 10485
1) "DEL"
2) "vvmusiclive_kroom_receive_k_user_gift_detail_list_927348780_3466"
1) (integer) 89211 2) (integer) 2018-11-02 10:05:31 3) (integer) 50708
1) "COMMAND"
...
# 处理前
1) (integer) 89209 2) (integer) 2018-11-02 10:03:33 3) (integer) 48990
1) (integer) 89210 2) (integer) 2018-11-02 10:03:40 3) (integer) 10485
1) (integer) 89211 2) (integer) 2018-11-02 10:05:31 3) (integer) 50708
...
# 处理后
1) 1) (integer) 89209
2) (integer) 2018-11-02 10:03:33
3) (integer) 48990
2) 1) (integer) 89210
2) (integer) 2018-11-02 10:03:40
3) (integer) 10485
3) 1) (integer) 89211
2) (integer) 2018-11-02 10:05:31
3) (integer) 50708
...
将处理步骤封装成shell函数,便于多实例调用。每天每个redis实例生成一个慢日志文件,以日期和端口命名文件。最终的redis_slowlog.sh内容如下:
#!/bin/bash
cd ~/redis_slowlog
function format_slowlog {
filename=`date "+%Y%m%d"`_$1.log
tmpfilename=tmp_slowlog_$1.txt
/home/redis/redis-3.2.3/src/redis-cli -p $1 --no-raw slowlog get 128 |
gawk '{ if($0~/1\) \(integer\)/) {$1="";sub("^ *","");} else if($0~/2\) \(integer\)/) {gsub($3,strftime("%Y-%m-%d %H:%M:%S",$3));sub("^ *","");} else if($0~/3\) \(integer\)/) {sub("^ *","");} else if ($0~/4\) +1\)/) {gsub(/4\)/," ",$0);} {print $0}}' >> $tmpfilename
gawk '/^1\)/{print s;s=""};{ s=(s" "$0)};END{print s } ' $tmpfilename | sort | uniq |
sed 's/ /\n /g' | gawk '/^ 1\) \(integer\)/{rc =rc+1;rowdata=rc") \t" $1" "$2" "$3"\n\t"$4" "$5" "$6" "$7"\n\t"$8" "$9" "$10;print rowdata};/^ /{print "\t"$0}' > $filename
}
format_slowlog 20001
format_slowlog 20002
format_slowlog 20003
format_slowlog 20004
format_slowlog 20005
format_slowlog 20006
format_slowlog 20007
format_slowlog 20008
redis slowlog的内容变化较快,因此10秒收集一次。考虑到生成的文件较多,并且太久以前的文件作用不大,只保留三天慢日志文件。调度使用crontab实现:
* * * * * /root/redis_slowlog.sh
* * * * * sleep 10; /root/redis_slowlog.sh
* * * * * sleep 20; /root/redis_slowlog.sh
* * * * * sleep 30; /root/redis_slowlog.sh
* * * * * sleep 40; /root/redis_slowlog.sh
* * * * * sleep 50; /root/redis_slowlog.sh
0 0 * * * rm -f /root/redis_slowlog/tmp_slowlog*.txt
0 0 * * * find /root/redis_slowlog/* -type f -mtime +3 -exec rm {} \;