Tomcat应用报redis超时的故事

转载:http://www.cnblogs.com/xinzhiyu/p/5910267.html

北京时间 2016年9月26日  17:26:30 PM

时间停留在N天前，线上应用总是时不时的出现用户登录失败的现象，喝了杯茶，细细品味下它的问题君存在的过程

业务背景介绍　　　　　　　　　　　 　　　　　　　　　　　　

系统架构是通过分布式的方式进行部署的，登录的时候不会调用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状况

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了