Redis 性能問題排查：slowlog 和排隊延時

1、Redis Slowlog介紹

[Redis Slowlog]是排查性能問題關鍵監控指標。它是記錄Redis queries運行時間超時特定閥值的系統。
這類慢查詢命令被保存到Redis服務器的一個定長隊列，最多保存slowlog-max-len(默認128）個慢查詢命令。
當慢查詢命令達到128個時，新產生的慢查詢被加入前，會從隊列中刪除最舊的慢查詢命令。

1.1  Redis Slowlog的配置

redis slowlog經過2個參數配置管理，默認命令耗時超過10毫秒，就會被記錄到慢查詢日誌隊列中；隊列默認保存最近產生的128個慢查詢命令。
slowlog-log-slower-than: 慢查詢閥值,單位微秒. 默認100000(10毫秒);
生產環境設置1ms,由於Redis是single thread,若是命令都是1ms以上,則實例的吞吐量只有1000QPS.
slowlog-max-len: 慢查詢存儲的最大個數,默認128;
生產設置設置大於1024,由於slowlog會省略過多的參數，慢查詢不會佔用過多的內存；
慢查詢隊列滿後,淘汰最老的慢查詢實體。

1.2  Redis Slowlog讀取

redis-cli客戶端經過slowlog get指令獲取最新10條慢查詢命令。
固然各語言的client也實現對應的接口。

示例：獲取最近2個慢查詢命令 
127.0.0.1:6381> SLOWLOG get 2
1) 1) (integer) 6
   2) (integer) 1458734263
   3) (integer) 74372
   4) 1) "hgetall"
      2) "max.dsp.blacklist"
2) 1) (integer) 5
   2) (integer) 1458734258
   3) (integer) 5411075
   4) 1) "keys"
      2) "max.dsp.blacklist"
分析slowlog query：
  以第一個HGET命令爲例分析，每一個slowlog實體共4個字段：
  * 字段1：1個整數,表示這個slowlog出現的序號,server啓動後遞增, 當前爲6.
  * 字段2：表示查詢執行時的Unix時間戳.
  * 字段3：表示查詢執行微妙數,當前是74372微妙,約74ms.
  * 字段4: 表示查詢的命令和參數,若是參數不少或很大,只會顯示部分並給數參數個數;
  當前命令是"hgetall"   "max.dsp.blacklist"

1.3  Redis Slowlog只計算命令的執行時間

如MySQL/MongoDB等常見數據庫，慢查詢的query_time都會包含命令全部耗時，包含鎖等待這類時間； 而Redis的慢查詢query_time只記錄本身「被cpu服務的時間」，不包含排隊等待、IO等待（如AOF SYNC）這類時間。
理解這點很是重要

參考：
    The Redis Slow Log is a system to log queries that exceeded a 
specified execution time. The execution time does not include I/O 
operations like talking with the client, sending the reply and so forth,
but just the time needed to actually execute the command (this is the only
stage of command execution where the thread is blocked and can not serve
other requests in the meantime).

2、Redis Slowlog測試

設定請求的響應時間(R),服務時間(S), 排隊延時（Q).
R = S + Q

咱們回到Redis的Slowlog問題上，上節已說slowlog只計算Redis命令被服務的時間，並不包含命令的排隊延遲時間。
2.1  如今作個測試：
一、redis實例port=6379,分別打開兩個session. session-1模擬一個執行耗時6秒的大命令debug sleep 6；隔幾秒後session-2執行一個簡單的set a b的命令。
二、2個sessions的命令執行完成後，查看redis slowlog記錄的命令耗時（slowlog-log-slower-than設置0）

session1:
rendeMacBook-Pro:~ rentom$ redis-cli
127.0.0.1:6379> debug sleep 6
OK
(6.00s)

session2:
127.0.0.1:6379> set name tom
OK
(5.14s)
127.0.0.1:6379> slowlog get
1) 1) (integer) 15
   2) (integer) 1538980614
   3) (integer) 4
   4) 1) "set"
      2) "name"
      3) "tom"
   5) "127.0.0.1:53738"
   6) ""
2) 1) (integer) 14
   2) (integer) 1538980614
   3) (integer) 6001061
   4) 1) "debug"
      2) "sleep"
      3) "6"
   5) "127.0.0.1:53737"
   6) ""

2.2  測試結論
一、從redis響應時間監控(min列），可見set name tom命令耗時5.14s；
但從redis slowlog中查看set name tom命令耗時爲4微秒，可見slowlog沒有記錄set命令排隊延遲等待的時間。
二、因Redis是單線程模型，debug sleep阻塞了set命令，set命令的總體響應時間(R)是5.14S，而其服務時間(S)爲4微秒，排隊延遲(Q)約爲5.14秒。

3、Redis Single-threads的問題

Redis Server是單線程的處理(bgsave或aof重寫時會Fork子進程處理），同一時間只能處理一個命令，而且是同步完成的。
從上節的測試中可見，set命令服務時間只有4微秒，但被debug sleep 6命令阻塞後，響應時間變成5.14秒。
因此RD和DBA在設計keyspace和訪問模式時，應儘可能避免使用耗時較大的命令。
在理想狀態下，Redis單實例能處理8~10w的QPS, 若是大量的redis命令大量耗時大於1ms, 其實QPS只能達到1000基於幾百。
Redis出現耗時大的命令，致使其餘全部請求被阻塞等待，redis處理能力急劇退化，易致使整個服務鏈雪崩。