Tomcat应用报redis超时的故事

北京时间 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飙升问题，于是更改持久化策略

先说一下持久化分为两种方式，第一种为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了

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

在