redis超时排查
2019-05-07 本文已影响4人
头发茂密的程序员
现象：服务起不来， log显示在初始化时从redis加载数据失败，程序自动退出
1. 问题确认
先查看服务连接的那台redis的slowlog 看看是不是读取数据超时
指令格式为 redis-cli.exe -p xxxx sloglog get num
-p表示指定端口，缺省值为6379
num缺省值为10
[root@slave1(101) ~]# /homed/redis/bin/redis-cli.exe -p 8888 sloglog get
...
7) 1) (integer) 186509
2) (integer) 1557194683
3) (integer) 80199888 #耗时ms
4) (integer) 2
5) "fd=162,peerip=192.168.2.113,peerport=48740,SrvTypeID=41612"
6) 1) "processHValsCommand"
2) "dtvs_column_program"
...
从redis日志查到失败的这条获取指令耗时 80199888ms, 就是80s,远大于程序设置的40s等待时间. 确认是redis读取数据超时导致.
2.问题排查
先确认数据大小, 是否是海量数据导致
[root@slave1(101) ~]# /homed/redis/bin/redis-cli.exe -p 8888 hlen dtvs_column_program
[redisFormatCommandArgv] send ipanel protocol msg(39 bits):
("*2\r\n$4\r\nhlen\r\n$19\r\ndtvs_column_program\r\n")
[redisBufferRead] read ipanel protocol msg(10 bytes):
(":1669675\r\n")
(integer) 1669675
发现数据量是百万级不算多, 并且返回长度的时候有将近一秒钟的卡顿,
再确认服务器cpu和内存情况
[root@slave1(101) ~]# top
top - 10:32:59 up 225 days, 23:06, 1 user, load average: 0.09, 0.28, 0.32
Tasks: 244 total, 2 running, 241 sleeping, 0 stopped, 1 zombie
Cpu(s): 9.6%us, 2.8%sy, 0.0%ni, 82.9%id, 4.5%wa, 0.0%hi, 0.3%si, 0.0%st
Mem: 8010180k total, 6642364k used, 1367816k free, 41836k buffers
Swap: 8388600k total, 8321800k used, 66800k free, 143812k cached
#
#
[root@slave1(101) ~]# free -m
total used free shared buffers cached
Mem: 7822 6487 1335 0 45 135
-/+ buffers/cache: 6306 1516
Swap: 8191 8126 65
发现服务器swap消耗很大, 由此怀疑是倒swap导致
Linux (以及其他一些操作系统) 可以把内存页存储在硬盘上，反之也能将存储在硬盘上的内存页再加载进内存，这种机制使得内存能够得到更有效的利用。
如果内存页被系统移到了swap文件里，而这个内存页中的数据恰好又被redis用到了（例如要访问某个存储在内存页中的key），系统就会暂停redis进程直到把需要的页数据重新加载进内存。这个操作因为牵涉到随机I/O，所以很慢，会导致无法预料的延迟。
所以更具redis进程的pid查询下redis进程的内存布局
[root@slave2(102) /home/redis/bin]# ps aux | grep redis
root 2946 1.5 11.1 27960492 896488 ? Ssl Mar17 1161:55 ./redis-server.exe slave pub8888Slave2 /homed/redis/bin/../config/redis-pub8888.conf
root 2952 0.5 0.0 51180 3372 ? Ssl Mar17 405:20 ./redis-sentinel.exe /homed/redis/bin/../config/sentinel-pub8887.conf
[root@slave2(102) /homed/redis/bin]# cd /proc/2946/
[root@slave2(102) /proc/2946]# ls
attr cgroup coredump_filter environ fdinfo loginuid mountinfo net oom_score personality schedstat stack status wchan
autogroup clear_refs cpuset exe io maps mounts numa_maps oom_score_adj root sessionid stat syscall
auxv cmdline cwd fd limits mem mountstats oom_adj pagemap sched smaps statm task
在这里你会发现一个名为smaps 的文件，它描述了redis进程的内存布局 (假定你使用的是Linux 2.6.16或者更新的版本)。这个文件包括了很多进程所使用内存的细节信息，其中有一项叫做Swap的正是我们所关心的。不过仅看这一项是不够的，因为smaps文件包括有redis进程的多个不同的的内存映射区域的使用情况（进程的内存布局远不是线性排列那么简单）。
从我们对所有进程的内存交换情况感兴趣以来，我们首先要做的事情是使用grep命令显示进程的smaps文件
[root@slave2(102) /proc/2946]# cat smaps | grep 'Swap:'
Swap: 0 kB
Swap: 0 kB
Swap: 4 kB
Swap: 4 kB
Swap: 4459156 kB
Swap: 0 kB
Swap: 52 kB
Swap: 0 kB
Swap: 0 kB
Swap: 1649036 kB
Swap: 24 kB
Swap: 0 kB
Swap: 6388 kB
Swap: 24 kB
Swap: 496 kB
Swap: 0 kB
假如所有的数据显示为0kb或者某些数据偶尔显示为4kb，表示当前一切正常。实际上我们的例子是一个真实的运行着Redis并每秒为数百的用户提供服务，会显示更多的交换页。为了研究是否存在一个严重的问题，我们改变命令打印出分配的内存尺寸
[root@slave2(102) /proc/2946]# cat smaps | egrep '^(Swap|Size)'
Size: 1200 kB
Swap: 0 kB
Size: 36 kB
Swap: 0 kB
Size: 156 kB
Swap: 52 kB
Size: 132 kB
Swap: 24 kB
Size: 3628 kB
Swap: 496 kB
Size: 128 kB
Swap: 0 kB
Swap: 4 kB
Size: 18264064 kB
Swap: 4459172 kB
Size: 4 kB
Swap: 0 kB
Size: 680 kB
Swap: 0 kB
Size: 7847936 kB
Swap: 1649572 kB
Size: 132 kB
Swap: 24 kB
Size: 65404 kB
Swap: 0 kB
Size: 24576 kB
Swap: 6392 kB
Size: 564 kB
Swap: 0 kB
Size: 412 kB
Swap: 0 kB
在输出信息中，你能看到有好些个较大的内存分配18264064kb（有4459172kb的交换），因此可能会产生任何的问题
假如进程的内存有相当部分花在了swap上，那么你的延迟可能就与swap有关。假如redis出现这种情况那么可以用 vmstat 命令来验证一下猜测：
[root@slave2(102) /proc/2946]# vmstat 1
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
2 1 8388600 1317960 7160 25988 10 4 822 332 0 0 21 8 64 7 0
2 1 8388600 1317580 6460 25944 0 0 3384 0 34749 101745 21 6 55 18 0
1 2 8388600 1318936 5384 26900 0 0 5684 36 35252 102194 21 7 53 20 0
2 1 8388600 1316876 5792 28580 32 4 5860 52 35057 101769 20 6 53 20 0
3 1 8388600 1322728 4128 23092 0 0 3288 296 35850 102399 20 8 51 21 0
2 1 8388600 1324216 3896 21892 0 0 3132 4 35183 102094 20 6 55 19 0
0 1 8388600 1324712 3872 21332 0 0 2792 0 35290 102133 20 7 54 19 0
3 1 8388600 1324340 4036 21496 0 0 6096 12 35086 101848 20 7 51 22 0
2 1 8388600 1327812 4032 18312 0 0 2220 56 35640 101922 21 6 53 20 0
3 1 8388600 1331160 3632 15652 0 0 1828 132 35217 101961 21 6 52 21 0
3 3 8388600 1331904 5148 14708 64 8 3056 52 35154 101981 20 8 44 28 0
2 1 8388600 1324960 5756 20332 0 0 10296 4 35298 102324 20 6 55 19 0
3 1 8388600 1325828 4596 20056 0 0 3248 16 34736 101586 20 7 54 19 0
2 1 8388600 1326572 4208 19752 64 8 4360 72 35382 102168 20 7 52 21 0
3 1 8388600 1329424 3668 20096 0 0 4808 464 35802 102230 20 7 50 23 0
6 3 8388592 1323704 3968 25592 32 8 10420 264 36074 102460 21 7 46 26 0
3 1 8388600 1323580 3572 25472 0 8 5828 168 35500 102488 21 7 49 23 0
6 2 8388600 1320976 6528 26600 32 4 7836 184 35348 102614 22 6 46 26 0
7 2 8388600 1321100 7432 24652 32 4 4148 40 35001 101978 20 7 53 20 0
1 1 8388600 1326432 7280 19184 0 0 2616 1196 35605 102327 20 7 54 19 0
0 2 8388600 1327912 5856 20424 32 4 5208 104 35453 102292 21 6 55 19 0
4 1 8388600 1326904 5504 20324 0 0 3412 80 35506 102265 21 6 52 21 0
输出中我们最感兴趣的两行是si 和 so，这两行分别统计了从swap文件恢复到内存的数量和swap到文件的内存数量。如果在这两行发现了非0值那么就说明系统正在进行swap。
同时，可以用iostat命令来查看系统的全局I/O行为。
[root@slave2(102) /proc/2946]# iostat -xk 1
Linux 2.6.32-279.el6.x86_64 (slave2) 2019年05月07日 _x86_64_ (4 CPU)
avg-cpu: %user %nice %system %iowait %steal %idle
20.70 0.00 7.59 7.32 0.00 64.39
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
sdf 10.35 51.54 8.10 22.02 172.65 294.28 31.00 0.09 2.96 3.28 9.88
sda 12.76 47.86 11.90 3.05 555.81 203.65 101.57 0.03 1.97 4.04 6.04
sdc 13.64 47.69 12.78 2.96 568.34 202.61 97.97 0.02 1.47 3.93 6.19
sdb 13.31 47.59 12.54 2.92 566.86 202.04 99.47 0.01 0.93 3.66 5.66
sde 13.13 47.58 12.45 2.93 565.38 202.06 99.76 0.02 1.00 3.88 5.97
sdd 52.61 46.87 28.04 3.20 794.41 200.30 63.68 0.10 3.18 2.53 7.92
avg-cpu: %user %nice %system %iowait %steal %idle
21.52 0.00 6.58 31.65 0.00 40.25
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
sdf 0.00 32.00 5.00 7.00 24.00 156.00 30.00 0.13 10.92 3.42 4.10
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdc 439.00 1679.00 118.00 56.00 2452.00 6940.00 107.95 2.24 12.87 5.61 97.70
sdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sde 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdd 0.00 0.00 20.00 0.00 2048.00 0.00 204.80 0.11 5.55 0.80 1.60
avg-cpu: %user %nice %system %iowait %steal %idle
20.26 0.00 6.92 31.54 0.00 41.28
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
sdf 0.00 0.00 3.00 0.00 12.00 0.00 8.00 0.01 5.00 5.00 1.50
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdc 548.00 0.00 133.00 0.00 2948.00 0.00 44.33 1.15 8.69 7.42 98.70
sdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sde 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
sdd 0.00 1.00 20.00 4.00 2048.00 20.00 172.33 0.57 23.88 4.00 9.60
avg-cpu: %user %nice %system %iowait %steal %idle
20.67 0.00 6.20 28.17 0.00 44.96
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
sdf 0.00 76.00 1.00 5.00 4.00 324.00 109.33 0.13 21.50 6.50 3.90
sda 0.00 0.00 0.00 1.00 0.00 4.00 8.00 0.00 3.00 3.00 0.30
sdc 476.00 0.00 143.00 0.00 2656.00 0.00 37.15 1.28 8.85 6.83 97.70
sdb 0.00 0.00 0.00 1.00 0.00 4.00 8.00 0.00 3.00 3.00 0.30
sde 0.00 1.00 0.00 23.00 0.00 96.00 8.35 0.15 6.48 4.91 11.30
sdd 0.00 0.00 32.00 0.00 2096.00 0.00 131.00 0.64 20.12 2.72 8.70
发现sdc的负载经常在90%以上, 同时再看了下服务的内存情况,发现swap已经耗完了.
[root@slave2(102) /proc/2946]# free -m
total used free shared buffers cached
Mem: 7822 6532 1289 0 6 46
-/+ buffers/cache: 6479 1343
Swap: 8191 8191 0
于是查一下哪个进程在占用磁盘io
方法 iotop -oP
命令的含义：只显示有I/O行为的进程
Total DISK READ: 8.82 M/s | Total DISK WRITE: 22.09 K/s
PID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
58 be/4 root 0.00 B/s 0.00 B/s 0.00 % 99.99 % [kswapd0]
29732 be/4 root 4.87 M/s 0.00 B/s 0.00 % 1.94 % ./filebeat
1148 be/4 root 7.36 K/s 7.36 K/s 0.00 % 1.44 % [kjournald]
28869 be/4 root 7.36 K/s 0.00 B/s 0.00 % 0.45 % top
2946 be/4 root 18.41 K/s 11.05 K/s 0.00 % 0.19 % ./redis-server.exe slave pub8888Slave2 /homed/redis/bin/../config/redis-pub8888.conf
13034 be/4 root 0.00 B/s 7.36 K/s 0.00 % 0.03 % java -Dproc_journalnode -Xmx24000m -Djava.net.preferIPv4Stack=true -Dhadoop.log.dir=/wo~FA -Dhadoop.security.logger=INFO,RFAS org.apache.hadoop.hdfs.qjournal.server.JournalNode
发现有个和swap相关的[kswapd0]基本占用了所有io
$ pidstat -d 1
命令的含义：展示I/O统计，每秒更新一次
[root@slave2(102) /proc/2946]# pidstat -d 1
Linux 2.6.32-279.el6.x86_64 (slave2) 2019年05月07日 _x86_64_ (4 CPU)
14时20分31秒 PID kB_rd/s kB_wr/s kB_ccwr/s Command
14时20分32秒 58 0.00 461.54 0.00 kswapd0
14时20分32秒 576 7.69 0.00 0.00 flush-8:80
14时20分32秒 2278 0.00 3.85 0.00 zabbix_agentd
14时20分32秒 2946 23.08 19.23 0.00 redis-server.ex
14时20分32秒 2952 0.00 3.85 0.00 redis-sentinel.
14时20分32秒 2973 0.00 3.85 0.00 redis-server.ex
14时20分32秒 13034 973.08 138.46 0.00 java
14时20分32秒 20972 2092.31 580.77 0.00 java
14时20分32秒 PID kB_rd/s kB_wr/s kB_ccwr/s Command
14时20分33秒 58 0.00 28.00 0.00 kswapd0
14时20分33秒 2946 0.00 12.00 0.00 redis-server.ex
14时20分33秒 3033 0.00 4.00 0.00 redis-sentinel.
14时20分33秒 20972 2048.00 0.00 0.00 java
14时20分33秒 28869 8.00 0.00 0.00 top
14时20分33秒 PID kB_rd/s kB_wr/s kB_ccwr/s Command
14时20分34秒 58 0.00 572.00 0.00 kswapd0
14时20分34秒 2946 0.00 4.00 0.00 redis-server.ex
14时20分34秒 2952 0.00 4.00 0.00 redis-sentinel.
14时20分34秒 3054 0.00 4.00 0.00 redis-server.ex
14时20分34秒 3081 0.00 4.00 0.00 redis-server.ex
14时20分34秒 13034 8.00 160.00 0.00 java
14时20分34秒 20972 2304.00 176.00 0.00 java
14时20分34秒 PID kB_rd/s kB_wr/s kB_ccwr/s Command
14时20分35秒 58 0.00 196.00 0.00 kswapd0
14时20分35秒 1148 0.00 4.00 0.00 kjournald
14时20分35秒 1151 0.00 20.00 0.00 jbd2/sdf8-8
14时20分35秒 1581 172.00 0.00 0.00 rpcbind
14时20分35秒 2354 96.00 0.00 0.00 master
14时20分35秒 2946 0.00 4.00 0.00 redis-server.ex
14时20分35秒 3000 0.00 4.00 0.00 redis-server.ex
14时20分35秒 3087 0.00 4.00 0.00 redis-sentinel.
14时20分35秒 9780 232.00 0.00 0.00 pickup
14时20分35秒 20972 2076.00 0.00 0.00 java
14时20分35秒 PID kB_rd/s kB_wr/s kB_ccwr/s Command
14时20分36秒 58 0.00 4952.00 0.00 kswapd0
14时20分36秒 481 0.00 16.00 0.00 kjournald
14时20分36秒 1161 0.00 16.00 0.00 jbd2/sdb1-8
14时20分36秒 1992 128.00 0.00 0.00 snmpd
14时20分36秒 2946 0.00 4.00 0.00 redis-server.ex
14时20分36秒 2952 0.00 4.00 0.00 redis-sentinel.
14时20分36秒 2979 0.00 4.00 0.00 redis-sentinel.
14时20分36秒 20972 504.00 4356.00 0.00 java
14时20分36秒 28869 8.00 0.00 0.00 top
14时20分36秒 29732 2840.00 0.00 0.00 filebeat
14时20分36秒 PID kB_rd/s kB_wr/s kB_ccwr/s Command
14时20分37秒 58 0.00 472.00 0.00 kswapd0
14时20分37秒 1166 0.00 36.00 0.00 jbd2/sde1-8
14时20分37秒 1176 0.00 16.00 0.00 jbd2/sda1-8
14时20分37秒 2946 0.00 4.00 0.00 redis-server.ex
14时20分37秒 13034 104.00 20.00 0.00 java
14时20分37秒 20972 7152.00 616.00 0.00 java
发现除了kswapd0以外还有一个java进程在读io
再回到sdc所在的目录看看
root@slave2(102) /proc/2946]# df -h
文件系统 容量 已用 可用 已用%% 挂载点
/dev/sdf5 30G 20G 8.9G 69% /
tmpfs 3.9G 0 3.9G 0% /dev/shm
/dev/sdf1 485M 37M 423M 8% /boot
/dev/sdf6 30G 3.4G 25G 12% /home
/dev/sdf2 40G 9.0G 29G 24% /usr
/dev/sdf3 40G 999M 37G 3% /var
/dev/sdf8 404G 319G 65G 84% /work
/dev/sdd1 1.8T 869G 873G 50% /data5
/dev/sdb1 1.9T 896G 875G 51% /data2
/dev/sde1 1.9T 893G 878G 51% /data4
/dev/sdc1 1.9T 889G 881G 51% /data3
/dev/sda1 1.9T 889G 881G 51% /data1
[root@slave2(102) /proc/2946]# cd /data3/
[root@slave2(102) /data3]# ll
总用量 28
-rw-r--r--. 1 root root 10 5月 7 14:24 disk_test.txt
-rw-rw-r--. 1 root root 20 9月 15 2017 zb_disk_check.txt
drwxr-xr-x. 3 root root 4096 2月 18 2014 hadoopdata
drwx------. 2 root root 16384 2月 15 2014 lost+found
发现有一个disk_test.txt的文件一直都在刷新. 由此怀疑是其他同事在做磁盘测试导致
