业务背景介绍
系统架构是通过分布式的方式进行部署的,登录的时候不会调用redis数据,假如用户登录成功了,会跳转到其它的项目上,并根据从redis中查到的权限缓存,像是相应的数据模块
问题排查
问题君发飙最初手段
问题一:用户登录失败,系统巨卡无比
问题二:Tomcat抛出 connect timed out错误
2016-09-24 16:44:24,397 - [ERROR] [RedisClient]:269- java.net.SocketTimeoutException: connect timed out
redis.clients.jedis.exceptions.JedisConnectionException: java.net.SocketTimeoutException: connect timed out
at redis.clients.jedis.Connection.connect(Connection.java:134)
at redis.clients.jedis.BinaryClient.connect(BinaryClient.java:69)
at redis.clients.jedis.Connection.sendCommand(Connection.java:79)
at redis.clients.jedis.BinaryClient.exists(BinaryClient.java:99)
at redis.clients.jedis.Client.exists(Client.java:29)
at redis.clients.jedis.Jedis.exists(Jedis.java:92)
at redis.clients.jedis.ShardedJedis.exists(ShardedJedis.java:48)
at com.tools.common.redis.client.RedisClient.exists(RedisClient.java:267)
at com.group.erp.rpc.dubbo.service.impl.ActionRpcServiceImpl.getActionList(ActionRpcServiceImpl.java:23)
at com.alibaba.dubbo.common.bytecode.Wrapper1.invokeMethod(Wrapper1.java)
at com.alibaba.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:46)
at com.alibaba.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:72)
at com.alibaba.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:55)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:38)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:73)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:68)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:42)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:78)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:60)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:108)
at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:84)
at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:170)
at com.alibaba.dubbo.remoting.transport.dispather.ChannelEventRunnable.run(ChannelEventRunnable.java:78)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.net.SocketTimeoutException: connect timed out
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at redis.clients.jedis.Connection.connect(Connection.java:129)
... 34 more
按照常规思路进行排查
查找问题君之网卡流量状况
:sar -n DEV 1
09时00分30秒 IFACE rxpck/s txpck/s rxkB/s txkB/s rxcmp/s txcmp/s rxmcst/s 09时00分31秒 lo 0.00 0.00 0.00 0.00 0.00 0.00 0.00 09时00分31秒 eth1 873.74 257.58 66.75 49.75 0.00 0.00 0.00
查找问题君之CPU状况
:top
[root@ZWCLC6X-10939 ~]# top top - 08:58:52 up 1 day, 15:05, 1 user, load average: 0.00, 0.00, 0.00 Tasks: 187 total, 1 running, 186 sleeping, 0 stopped, 0 zombie Cpu(s): 0.2%us, 0.2%sy, 0.0%ni, 98.7%id, 0.1%wa, 0.3%hi, 0.5%si, 0.0%st Mem: 16333752k total, 12914752k used, 3419000k free, 286716k buffers Swap: 1048572k total, 0k used, 1048572k free, 1013568k cached
查找问题君之内存状况
:free -m
total used free shared buffers cached Mem: 15950 14612 1338 0 279 990 -/+ buffers/cache: 11342 4608 Swap: 1023 997 26
这里发现了一个问题,服务器的内存资源居高不下,暂且不考虑服务器资源的正常与否
查找问题君之可疑进程状况
ps -ef 显示系统进程
这里不方便把服务器开启了那些进程罗列到此处,还请见谅;最后的分析结果就是,并无异常进程
这就奇怪了,到底是哪的问题呢?继续查找
查找问题君之生产环境应用
生产环境有两个java项目都调用了这个服务器的redis服务,然后找到了这两个项目分别查看日志,几乎在相同时间都抛出了Time out的错误,因此断定应该是redis单方面的问题
查找问题君之生产环境redis服务
查看了redis日志,并没有什么报错请求
[1008] 24 Sep 17:17:20.378 - Accepted XX.XX.XX.XX:40688
[1008] 24 Sep 17:17:20.394 - Accepted XX.XX.XX.XX:40691
[1008] 24 Sep 17:17:20.470 - Accepted XX.XX.XX.XX:40692
[1008] 24 Sep 17:17:20.470 - Accepted XX.XX.XX.XX:40693
[1008] 24 Sep 17:17:20.484 - Accepted XX.XX.XX.XX:55622
[1008] 24 Sep 17:17:20.486 - Accepted XX.XX.XX.XX:40697
[1008] 24 Sep 17:17:20.488 - Accepted XX.XX.XX.XX:55624
查找问题君之redis压力测试
使用redis-benchmark测试了redis的压力,也没有什么问题。
查找问题君之redis慢查询
怀疑是有慢查询 连接数不够用 等待了 导致超时了
有这么几个命令:
./redis-cli -h 127.0.0.1 -p 6378 # 这个是连接上本机的6378的redis
auth password #如果redis设置的有密码,使用auth进行密码验证
CONFIG GET slowlog-log-slower-than #(10000us,Redis中的执行单位是微秒,相当于10ms)
CONFIG GET slowlog-max-len (最多存储128条慢日志,应该是默认的吧?)
SLOWLOG LEN #查看redis存储的慢查询记录,默认查看128条
SLOWLOG GET # 查看redis存储的慢查询记录,默认10条
6) 1) (integer) 166
2) (integer) 1474962558
3) (integer) 55972 # 这个是慢查询时间,微秒级别的,1秒=1000毫秒,1毫秒=1000微妙
4) 1) "SETEX"
2) "company_info_nan857920"
3) "7200"
4) "\x1f\x8b\b\x00\x00\x00\x00\x00\x00\x00\xedUKo\x1bU\x14\xbeq\xc8\xbb\r\xa1\b!\x16\x85\x05\xe2)a\xc7\x8dJ\x12uG\xca\xc2\xe0V\x15)\x0b\x96S\xcf\x8d3\xc5\x9e\x99\xcc\\'\x0e\x0b\xd4\xb4u\x1c'N\x9d\x904\xad\x1b\xf7\x11\xd5\xa1\t4N+L\xe2\xfa\xd1JH\xac\xf9\x0b\x88\xce\xb5g\x16(K\xb6\x9c\xeby\xd8A\xb0cYK\x1e\x9f\xf3\x9d\xef<\xee9g\xae\x1f\xfe\x89\xdaT\x05\xbd\x17\x90\xc2n\x95\x9fvGT... (1218 more
从上面可以看出一个满查询在55毫秒左右,项目的配置文件在10秒左右,所以不存在超时的问题
查找问题君之redis内存
怀疑redis的内存用到上线,因此查看了redis的配置
maxmonery # 我的配置文件没有设置,默认是不限制内存
查找问题君之redis内存使用状况
#./redis-cli -h 127.0.0.1 -p 6378 # 这个是连接上本机的6378的redis
> info # 查看redis信息
#Server
XXXXXXXXXXXX
#Clients
XXXXXXXXXXXX
#Memory
used_memory:28507480
used_memory_human:27.19M
used_memory_rss:51208192
used_memory_peak:51844256
used_memory_peak_human:49.44M
used_memory_lua:33792
mem_fragmentation_ratio:1.80
mem_allocator:libc
#Persistence
XXXXXXXXXX
#Stats
XXXXXXXXXX
#Replication
XXXXXXXXXX
#CPU
XXXXXXXXXX
#Keyspace
XXXXXXXXXX
介绍Memory的参数信息:
查看了redis使用内存很小,才使用了27.19M,排除了redis的内存使用情况
查找问题君之初步定型问题
使用了speedtest-cli 命令测试了本机的网速情况
speedtest-cli命令介绍:
参考:http://www.linuxde.net/2014/01/15561.html
$ wget https://raw.github.com/sivel/speedtest-cli/master/speedtest_cli.py
$ chmod a+rx speedtest_cli.py
$ sudo mv speedtest_cli.py /usr/local/bin/speedtest-cli
$ sudo chown root:root /usr/local/bin/speedtest-cli
测试结果:
使用这个命令查看本机网络,貌似有问题,于是那了两台机器之间互传了一个较大的文件,查看了速度,经测试速度在5MB-6MB左右,因此排除了网络问题】
查找问题君之数据持久化导
开始认为是持久化导致的磁盘IO飙升问题,于是更改持久化策略
先说一下持久化分为两种方式,第一种为AOF,第二种为save的方式,格式大概为
方式一:
################################ 快照 #################################
#
# 把数据库存到磁盘上:
#
# save <seconds> <changes>
#
# 会在指定秒数和数据变化次数之后把数据库写到磁盘上。
#
# 下面的例子将会进行把数据写入磁盘的操作:
# 900秒(15分钟)之后,且至少1次变更
# 300秒(5分钟)之后,且至少10次变更
# 60秒之后,且至少10000次变更
#
# 注意:你要想不写磁盘的话就把所有 "save" 设置注释掉就行了。
#save 900 1
#save 300 10
#save 60 10000
方式二:
############################## 纯累加模式 ###############################
# 默认情况下,Redis是异步的把数据导出到磁盘上。这种情况下,当Redis挂掉的时候,最新的数据就丢了。
# 如果不希望丢掉任何一条数据的话就该用纯累加模式:一旦开启这个模式,Redis会把每次写入的数据在接收后都写入 appendonly.aof 文件。
# 每次启动时Redis都会把这个文件的数据读入内存里。
#
# 注意,异步导出的数据库文件和纯累加文件可以并存(你得把上面所有"save"设置都注释掉,关掉导出机制)。
# 如果纯累加模式开启了,那么Redis会在启动时载入日志文件而忽略导出的 dump.rdb 文件。
#
# 重要:查看 BGREWRITEAOF 来了解当累加日志文件太大了之后,怎么在后台重新处理这个日志文件。
appendonly yes
# 纯累加文件名字(默认:"appendonly.aof")
# appendfilename appendonly.aof
appendfilename "appendonly.aof"
# fsync() 请求操作系统马上把数据写到磁盘上,不要再等了。
# 有些操作系统会真的把数据马上刷到磁盘上;有些则要磨蹭一下,但是会尽快去做。
#
# Redis支持三种不同的模式:
#
# no:不要立刻刷,只有在操作系统需要刷的时候再刷。比较快。
# always:每次写操作都立刻写入到aof文件。慢,但是最安全。
# everysec:每秒写一次。折衷方案。
#
# 默认的 "everysec" 通常来说能在速度和数据安全性之间取得比较好的平衡。
# 如果你真的理解了这个意味着什么,那么设置"no"可以获得更好的性能表现(如果丢数据的话,则只能拿到一个不是很新的快照);
# 或者相反的,你选择 "always" 来牺牲速度确保数据安全、完整。
#
# 如果拿不准,就用 "everysec"
# appendfsync always
appendfsync everysec
# appendfsync no
# 如果AOF的同步策略设置成 "always" 或者 "everysec",那么后台的存储进程(后台存储或写入AOF日志)会产生很多磁盘I/O开销。
# 某些Linux的配置下会使Redis因为 fsync() 而阻塞很久。
# 注意,目前对这个情况还没有完美修正,甚至不同线程的 fsync() 会阻塞我们的 write(2) 请求。
#
# 为了缓解这个问题,可以用下面这个选项。它可以在 BGSAVE 或 BGREWRITEAOF 处理时阻止 fsync()。
#
# 这就意味着如果有子进程在进行保存操作,那么Redis就处于"不可同步"的状态。
# 这实际上是说,在最差的情况下可能会丢掉30秒钟的日志数据。(默认Linux设定)
#
# 如果你有延迟的问题那就把这个设为 "yes",否则就保持 "no",这是保存持久数据的最安全的方式。
no-appendfsync-on-rewrite yes
# 自动重写AOF文件
#
# 如果AOF日志文件大到指定百分比,Redis能够通过 BGREWRITEAOF 自动重写AOF日志文件。
#
# 工作原理:Redis记住上次重写时AOF日志的大小(或者重启后没有写操作的话,那就直接用此时的AOF文件),
# 基准尺寸和当前尺寸做比较。如果当前尺寸超过指定比例,就会触发重写操作。
#
# 你还需要指定被重写日志的最小尺寸,这样避免了达到约定百分比但尺寸仍然很小的情况还要重写。
#
# 指定百分比为0会禁用AOF自动重写特性。
auto-aof-rewrite-percentage 100
auto-aof-rewrite-min-size 64mb
# lua
lua-time-limit 5000
注掉了从的持久化,主注掉save模式,开启AOF模式,可是io高的问题依旧没有解决,于是乎就有了下文
查找问题君之磁盘IO状况
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sdb 0.00 59.00 574.00 99.00 21272.00 1272.00 33.50 6.02 9.01 1.34 89.90
sda 0.00 0.00 0.00 3.00 0.00 24.00 8.00 0.00 0.00 0.00 0.00
dm-0 0.00 0.00 568.00 158.00 21080.00 1272.00 30.79 6.04 8.38 1.24 89.90
看到这个界面,好像找到了点头绪,服务器的磁盘IO较高,但是小编这里也提出了疑问,redis的数据全部存放到了sdb银盘上,而且redis的程序也都是在sdb上面,那为什么服务器的sda的
IO资源占用如此之高呢?
顺藤摸瓜>>>就从高IO的线索查找问题根源:
检查是什么进程占用了如此高系统盘IO?
iotop
iotop执行命令结果,发现一个占用资源特别高的进程
检查发现,这个进程存在的作用是,当系统的物理内存耗尽时候,系统会激活此进程,以来调用swap分区。
这下有点明白其中的道道了,问题原因大概如下:
检查都有那些系统应用占用了swap分区,编写脚本:
#!/bin/bash
###############################################################################
# 日期 : 2016-09-27
# 作者 : sean
# Email : linux_no1@126.com
# 版本 : 1.0
# 脚本功能 : 列出正在占用swap的进程。
###############################################################################
echo -e "PID\t\tSwap\t\tProc_Name"
for pid in `ls -l /proc | grep ^d | awk '{ print $9 }'| grep -v [^0-9]`
# /proc目录下所有以数字为名的目录(进程名是数字才是进程,其他如sys,net等存放的是其他信息)
do
if [ $pid -eq 1 ];then continue;fi # Do not check init process
# 让进程释放swap的方法只有一个:就是重启该进程。或者等其自动释放。
# 如果进程会自动释放,那么我们就不会写脚本来找他了,找他都是因为他没有自动释放。
# 所以我们要列出占用swap并需要重启的进程,但是init这个进程是系统里所有进程的祖先进程
# 重启init进程意味着重启系统,这是万万不可以的,所以就不必检测他了,以免对系统造成影响。
grep -q "Swap" /proc/$pid/smaps 2>/dev/null #检查是否占用swap分区
if [ $? -eq 0 ];then
swap=$(awk '/Swap/{ sum+=$2;} END{ print sum }' /proc/$pid/smaps) #统计占用的swap分区的大小 单位是KB
proc_name=$(ps aux | grep -w "$pid" | awk '!/grep/{ for(i=11;i<=NF;i++){ printf("%s ",$i); }}') #取出进程的名字
if [ $swap -gt 0 ];then #判断是否占用swap,只有占用才会输出
echo -e "$pid\t${swap}\t$proc_name"
fi
fi
done | sort -k2 -n | awk -F'\t' '{
if($2<1024)
printf("%-10s\t%15sKB\t%s\n",$1,$2,$3);
else if($2<1048576)
printf("%-10s\t%15.2fMB\t%s\n",$1,$2/1024,$3);
else
printf("%-10s\t%15.2fGB\t%s\n",$1,$2/1048576,$3);
}'
执行结果,发现
redis的进程全部存放在了swap分区中,果然是这样。
修改内核参数,合理分配内存使用
A.释放物理内存,并且叫新应用获取物理内存。
参考地址:http://www.cnblogs.com/minideas/p/3796505.html
1.在释放内存之前,检查可用内存多少
free -m
输出结果略
2.手动释放内存
echo 1 > /proc/sys/vm/drop_caches
3.释放完成后,检查可用内存是否进行了释放
free -m
输出结果略
经过上述的三个命令,发现内存确实进行了释放。
4.重启redis服务
5.检查swap分区使用
重启了redis发现内存走的依旧是swap分区,物理内存还有很多可用内存,但是系统为什么分给应用swap分区呢?
B.修改系统内核参数,叫所有的应用尽量使用物理内存,避免使用swap分区。
参考地址:http://davidbj.blog.51cto.com/4159484/1172879/
仔细看,物理内存还有将近1GB没有使用。但是swap已经开始被使用。怀疑是不是swappiness文件的值没有更改。
说明:在centos里面,swappiness的值的大小对如何使用swap分区是有着很大的联系的。swappiness=0的时候表示最大限度使用物理内存,然后才是 swap空间,swappiness=100的时候表示积极的使用swap分区,并且把内存上的数据及时的搬运到swap空间里面。两个极端,对于Centos的默认设置,这个值等于60,建议修改为10。具体这样做:
sysctl vm.swappiness=10
但是这只是临时的修改,如果系统重启会恢复默认的值60,所有还需要做下一步:
echo vm.swappiness=10 >> /etc/sysctl.conf
这样就可以了。
最后重新加载swap虚拟内存:
swapoff -a //关闭虚拟内存
swapon -a //开启虚拟内存
但是上面操作后,重启了redis应用,系统依旧分给了redis swap分区。
C. 最后重启服务器,并再次启动redis服务,最后问题得到了解决。swap分区为0了