Redis異常及使用總結

阿新 • • 發佈：2019-01-15

現象:各種釋出，和其他指令都失效

日誌:

com.lingyu.common.core.ServiceException: redis.clients.jedis.exceptions.JedisDataException: ERR only (P)SUBSCRIBE / (P)UNSUBSCRIBE / QUIT allowed in this context
	at com.lingyu.common.db.Redis.publish(Redis.java:1402)
	at com.lingyu.game.service.stat.StatRepository.publish(StatRepository.java:16)
	at com.lingyu.game.service.stat.StatManager.statRealTime(StatManager.java:232)
	at com.lingyu.game.service.job.JobManager.statRealTime(JobManager.java:336)
	at sun.reflect.GeneratedMethodAccessor203.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
	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:756)
Caused by: redis.clients.jedis.exceptions.JedisDataException: ERR only (P)SUBSCRIBE / (P)UNSUBSCRIBE / QUIT allowed in this context
	at redis.clients.jedis.Protocol.processError(Protocol.java:117)
	at redis.clients.jedis.Protocol.process(Protocol.java:151)
	at redis.clients.jedis.Protocol.read(Protocol.java:205)
	at redis.clients.jedis.Connection.readProtocolWithCheckingBroken(Connection.java:297)
	at redis.clients.jedis.Connection.getIntegerReply(Connection.java:222)
	at redis.clients.jedis.Jedis.publish(Jedis.java:2601)
	at com.lingyu.common.db.Redis.publish(Redis.java:1399)

現象 :早上後臺的訂閱執行緒無故退出，導致統計和監控失效長達5個小時左右

日誌:

原因:The error comes from the fact a Redis connection cannot be shared between publishers and subscribers. Actually you need a connection (or a pool of connections) for publishers, and just one dedicated connection for the subscriber thread. Running a single subscriber thread per process is usually enough.

由於訂閱執行緒因為某種原因逃逸，導致被阻塞的訂閱連線重新投入使用，一旦被用來做其他指令的操作，就報出了以上異常，訂閱過的連線不能用來做其他用處，否則就會有以上的問題。

2015-04-13 05:00:00.256 ERROR [Message SubScribe Monitor][SubScribeManager.java:127] - 訂閱執行緒無故退出
com.lingyu.common.core.ServiceException: redis.clients.jedis.exceptions.JedisConnectionException: Unexpected end of stream.
        at com.lingyu.common.db.Redis.subscribe(Redis.java:1439) ~[Redis.class:?]
        at com.lingyu.common.db.SubScribeManager.run(SubScribeManager.java:125) ~[SubScribeManager.class:?]
        at java.lang.Thread.run(Thread.java:745) [?:1.7.0_65]
Caused by: redis.clients.jedis.exceptions.JedisConnectionException: Unexpected end of stream.
        at redis.clients.util.RedisInputStream.ensureFill(RedisInputStream.java:198) ~[jedis-2.6.2.jar:?]
        at redis.clients.util.RedisInputStream.read(RedisInputStream.java:180) ~[jedis-2.6.2.jar:?]
        at redis.clients.jedis.Protocol.processBulkReply(Protocol.java:158) ~[jedis-2.6.2.jar:?]
        at redis.clients.jedis.Protocol.process(Protocol.java:132) ~[jedis-2.6.2.jar:?]
        at redis.clients.jedis.Protocol.processMultiBulkReply(Protocol.java:183) ~[jedis-2.6.2.jar:?]
        at redis.clients.jedis.Protocol.process(Protocol.java:134) ~[jedis-2.6.2.jar:?]
        at redis.clients.jedis.Protocol.read(Protocol.java:192) ~[jedis-2.6.2.jar:?]
        at redis.clients.jedis.Connection.readProtocolWithCheckingBroken(Connection.java:282) ~[jedis-2.6.2.jar:?]
        at redis.clients.jedis.Connection.getRawObjectMultiBulkReply(Connection.java:227) ~[jedis-2.6.2.jar:?]
        at redis.clients.jedis.JedisPubSub.process(JedisPubSub.java:108) ~[jedis-2.6.2.jar:?]
        at redis.clients.jedis.JedisPubSub.proceed(JedisPubSub.java:102) ~[jedis-2.6.2.jar:?]
        at redis.clients.jedis.Jedis.subscribe(Jedis.java:2496) ~[jedis-2.6.2.jar:?]
        at com.lingyu.common.db.Redis.subscribe(Redis.java:1435) ~[Redis.class:?]
        ... 2 more

被try{}catch(Exception e){} 的居然還會退出，很疑惑~~

查到了這篇文章：

https://github.com/xetorthio/jedis/issues/932

client-output-buffer-limit was the cause. redis-server closed the connections, leading to the exceptions.

client-output-buffer-limit

客戶端buffer控制。在客戶端與server進行的互動中,每個連線都會與一個buffer關聯,此buffer用來佇列化等待被client接受的響應資訊。如果client不能及時的消費響應資訊,那麼buffer將會被不斷積壓而給server帶來記憶體壓力.如果buffer中積壓的資料達到閥值,將會導致連線被關閉,buffer被移除。

buffer控制型別包括:normal -> 普通連線；slave ->與slave之間的連線；pubsub ->pub/sub型別連線，此型別的連線，往往會產生此種問題;因為pub端會密集的釋出訊息,但是sub端可能消費不足.
指令格式:client-output-buffer-limit <class> <hard> <soft> <seconds>",其中hard表示buffer最大值,一旦達到閥值將立即關閉連線;
soft表示"容忍值",它和seconds配合,如果buffer值超過soft且持續時間達到了seconds,也將立即關閉連線,如果超過了soft但是在seconds之後，buffer資料小於了soft,連線將會被保留.
其中hard和soft都設定為0,則表示禁用buffer控制.通常hard值大於soft.

生產線上調整引數(記憶體和配置同步修改):

127.0.0.1:6380> CONFIG GET client-output-buffer-limit
client-output-buffer-limit
normal 0 0 0 slave 268435456 67108864 60 pubsub 33554432 8388608 60

127.0.0.1:6380> config set client-output-buffer-limit 'normal 0 0 0 slave 268435456 67108864 60 pubsub 0 0 0'

redis.conf
client-output-buffer-limit pubsub 0 0 0

===========================================================

昨天又遇到俄羅斯地區後臺活動上傳不成功，我們的後臺活動是通過redos publish出去的，但發現publish失敗，試著手工publish 小位元組的是沒問題，大位元組的就失敗，info 也沒法檢視。

後臺確認原因是，內網區域網傳輸對包的大小進行了限制，超過一定大小的包，都無法進行傳輸，並導致連線失效。開啟限制，問題解決。

=============================================================

6470672人

平均下來每個人，887位元組記憶體佔用，608 AOF 磁碟佔用 344 RDB磁碟佔用

檔案cache需要額外佔用一半的記憶體佔用，所以大概就有10幾G的佔用

=============================================================

慢查詢獲取

slowlog get

127.0.0.1:6379> slowlog get 
 1) 1) (integer) 27
    2) (integer) 1417531320
    3) (integer) 24623
    4) 1) "info".0.1:6379> slowlog get 
 1) 1) (integer) 27
    2) (integer) 1417531320
    3) (integer) 24623
    4) 1) "info"

其中，各項指標表示：

A unique progressive identifier for every slow log entry. slowlog的流水號
The unix timestamp at which the logged command was processed. unix時間戳
The amount of time needed for its execution, in microseconds 平均耗時（注意，microseconds翻譯成微秒，而不是毫秒）.
The array composing the arguments of the command.

slowlog len 獲取總共的slow log數量

slowlog get number 根據數量獲取slowlog

=======================================

commandstats 部分記錄了各種不同型別的命令的執行統計資訊，比如命令執行的次數、命令耗費的 CPU 時間(單位毫秒)、執行每個命令耗費的平均 CPU 時間(單位毫秒)等等。對於每種型別的命令，這個部分都會新增一行以下格式的資訊：

cmdstat_XXX:calls=XXX,usec=XXX,usecpercall=XXX

10.104.5.98:6379>info commandstats
# Commandstats
cmdstat_get:calls=180608685,usec=470928529,usec_per_call=2.61
cmdstat_set:calls=147550519,usec=562225572,usec_per_call=3.81
cmdstat_del:calls=177224,usec=1643815,usec_per_call=9.28
cmdstat_exists:calls=14130110,usec=31402378,usec_per_call=2.22
cmdstat_incr:calls=1017,usec=3261,usec_per_call=3.21
cmdstat_mget:calls=666034,usec=18069595,usec_per_call=27.13
cmdstat_lpush:calls=103077132,usec=181583996,usec_per_call=1.76
cmdstat_lrange:calls=38777511,usec=138617427,usec_per_call=3.57
cmdstat_ltrim:calls=2056,usec=7622,usec_per_call=3.71
cmdstat_lrem:calls=103075076,usec=579401111,usec_per_call=5.62
cmdstat_zadd:calls=15900133,usec=56515414,usec_per_call=3.55
cmdstat_zincrby:calls=11747959,usec=196212310,usec_per_call=16.70
cmdstat_zrem:calls=257783,usec=1053833,usec_per_call=4.09
cmdstat_zrange:calls=7141527,usec=41950470,usec_per_call=5.87
cmdstat_zrevrangebyscore:calls=10,usec=51489,usec_per_call=5148.90
cmdstat_zcount:calls=16104028,usec=112221789,usec_per_call=6.97
cmdstat_zrevrange:calls=27497771,usec=582807534,usec_per_call=21.19
cmdstat_zscore:calls=8663683,usec=44001575,usec_per_call=5.08
cmdstat_zrank:calls=3,usec=43,usec_per_call=14.33
cmdstat_zrevrank:calls=15906400,usec=68891802,usec_per_call=4.33
cmdstat_hset:calls=10236125,usec=37507245,usec_per_call=3.66
cmdstat_hget:calls=1618802100,usec=2755577270,usec_per_call=1.70
cmdstat_hmset:calls=369619411,usec=4843444966,usec_per_call=13.10
cmdstat_hmget:calls=56015,usec=344231,usec_per_call=6.15
cmdstat_hincrby:calls=170633471,usec=884820311,usec_per_call=5.19
cmdstat_hdel:calls=44233,usec=201881,usec_per_call=4.56
cmdstat_hlen:calls=21724,usec=39834,usec_per_call=1.83
cmdstat_hgetall:calls=311374011,usec=3269118749,usec_per_call=10.50
cmdstat_hexists:calls=70864759,usec=285319509,usec_per_call=4.03
cmdstat_incrby:calls=2942269,usec=42251052,usec_per_call=14.36
cmdstat_decrby:calls=2050,usec=3616,usec_per_call=1.76
cmdstat_rename:calls=6472,usec=33326,usec_per_call=5.15
cmdstat_keys:calls=3636,usec=1974535725,usec_per_call=543051.62
cmdstat_dbsize:calls=9,usec=15,usec_per_call=1.67
cmdstat_ping:calls=46747,usec=61691,usec_per_call=1.32
cmdstat_type:calls=1,usec=3,usec_per_call=3.00
cmdstat_psync:calls=1,usec=3164,usec_per_call=3164.00
cmdstat_replconf:calls=21643928,usec=25568830,usec_per_call=1.18
cmdstat_info:calls=4,usec=3669,usec_per_call=917.25
cmdstat_config:calls=2,usec=37,usec_per_call=18.50
cmdstat_subscribe:calls=45505,usec=476993,usec_per_call=10.48
cmdstat_publish:calls=34572782,usec=262298295,usec_per_call=7.59
cmdstat_client:calls=3,usec=47628,usec_per_call=15876.00
cmdstat_eval:calls=2050,usec=76432,usec_per_call=37.28
cmdstat_slowlog:calls=1,usec=30,usec_per_call=30.00

redis.2.8.23 版本部署時會有兩個warning

[32555] 09 Nov 12:06:37.804 # WARNING you have Transparent Huge Pages (THP) support enabled in your kernel. This will create latency and memory usage issues with Redis. To fix this issue run the command 'echo never > /sys/kernel/mm/transparent_hugepage/enabled' as root, and add it to your /etc/rc.local in order to retain the setting after a reboot. Redis must be restarted after THP is disabled.
[32555] 09 Nov 12:06:37.804 # WARNING: The TCP backlog setting of 511 cannot be enforced because /proc/sys/net/core/somaxconn is set to the lower value of 128.

只要按照提示來就行:

echo never > /sys/kernel/mm/transparent_hugepage/enabled

echo 511 > /proc/sys/net/core/somaxconn

並加到 /etc/rc.local

==============================================

Redis ＂MISCONF Redis is configured to save RDB snapshots, but is currently not able to persist on disk＂

1.沒有配置 vm.overcommit_memory=1

2.磁碟空間不足

3.rdb檔案被刪除，解決辦法

<span style="color:#000000">CONFIG SET dir /data/redis/</span>

Redis異常及使用總結

Redis異常及使用總結

Redis異常及解決

pandas安裝若干異常及解決方案總結

RMI總結及可能產生的幾種異常及解決

“全棧2019”22篇Java異常學習資料及總結

redis 之 redis簡介及下載安裝

Redis部署及參數筆記

java web 常見異常及解決辦法

Redis基礎及入門

redis安裝及主從配置

一道正則練習及總結

Maven常見異常及解決方法

redis安裝及php擴展

redis cluster 實踐總結

緩存系列之三：redis安裝及基本數據類型命令使用

異常及File類概述

使用php-amqplib連接rabbitMQ 學習筆記及總結

異常及日誌使用與項目打包

postman 訪問 jenkins api 接口異常及處理

redis 安裝及啟動關閉

Redis異常及使用總結

相關推薦