Tomcat應用報redis超時的故事

餘二五發表於2017-11-16

業務背景介紹           

系統架構是通過分散式的方式進行部署的,登入的時候不會呼叫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) "x1fx8bx00x00x00x00x00x00x00xedUKox1bUx14xbeqxc8xbb
xa1!x16x85x05xe2)axc7x8dJx12uGxcaxc2xe0Vx15)x0bx96Sxcfx8d3xc5x9ex99xcc\`x0ex0bxd4xb4ux1c`Nx9dx904xadx1bxf7x11xd5xa1	4N+Lxe2xfaxd1JHxacxf9x0bx88xcexb5gx16(Kxb6x9cxebyxd8Axb0cYKx1ex9fxf3x9dxef<xee9gxaex1fxfex89xdaTx05xbdx17x90xc2nx95x9fvGT... (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的引數資訊:
Tomcat應用報redis超時的故事

檢視了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

測試結果:
Tomcat應用報redis超時的故事

使用這個命令檢視本機網路,貌似有問題,於是那了兩臺機器之間互傳了一個較大的檔案,檢視了速度,經測試速度在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分割槽。

這下有點明白其中的道道了,問題原因大概如下:
Tomcat應用報redis超時的故事

檢查都有那些系統應用佔用了swap分割槽,編寫指令碼:

#!/bin/bash
###############################################################################
# 日期 : 2016-09-27
# 作者 : sean
# Email : linux_no1@126.com
# 版本 : 1.0
# 指令碼功能 : 列出正在佔用swap的程式。
###############################################################################
echo -e "PID		Swap		Proc_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	${swap}	$proc_name"
          fi
          fi
         done | sort -k2 -n | awk -F`	` `{   
        if($2<1024)
           printf("%-10s	%15sKB	%s
",$1,$2,$3);
        else if($2<1048576)
           printf("%-10s	%15.2fMB	%s
",$1,$2/1024,$3);
        else
      printf("%-10s	%15.2fGB	%s
",$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/
Tomcat應用報redis超時的故事

仔細看,實體記憶體還有將近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了

本文轉自 xinsir999 51CTO部落格,原文連結:http://blog.51cto.com/xinsir/2050754,如需轉載請自行聯絡原作者


相關文章