北京時間 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了
在