29-案例篇：Redis響應嚴重延遲，如何解決？
阿新 • • 發佈：2021-12-22
MySQL的MyISAM引擎，主要依賴系統快取加速磁碟I/O的訪問
可如果系統中還有其他應用同時執行，MyISAM引擎很難充分利用系統快取
快取可能會被其他應用程式佔用，甚至被清理掉
所以並不建議，把應用程式的效能優化完全建立在系統快取上
最好能在應用程式的內部分配記憶體，構建完全自主控制的快取
或者使用第三方的快取應用，比如Memcached、Redis等
Redis是最常用的鍵值儲存系統之一，常用作資料庫、快取記憶體和訊息佇列代理等
Redis基於記憶體來儲存資料
不過，為了保證在伺服器異常時資料不丟失，很多情況下，要為它配置持久化
而這就可能會引發磁碟I/O的效能問題
案例
-
伺服器配置
# 服務端（192.168.1.6） # 機器配置：2cpu，4GB記憶體 # 預先安裝docker、sysstat、git、make包 # 客戶端（192.168.1.5） # 案例說明 案例由Python應用、Redis兩部分組成 Python應用是一個基於Flask的應用，它會利用Redis，來管理應用程式的快取 並對外提供三個HTTP介面 1. /：返回hello redis 2. /init/：插入指定數量的快取資料，如果不指定數量，預設的是5000條 快取的鍵格式為uuid 快取的值為good、bad或normal三者之一 3. /get_cache/<type_name>：查詢指定值的快取資料，並返回處理時間 其中，type_name引數只支援good,bad和normal（也就是找出具有相同value的key列表）
-
在服務端，執行命令，執行本次案例需要分析的應用
# [root@local_sa_192-168-1-6 ~]# docker run --name=redis -itd -p 10000:80 feisky/redis-server 2d1811589334f0f5615b1b85936ddbc4ee565b85d73c6bc887c4f5cadf9f195f # [root@local_sa_192-168-1-6 ~]# docker run --name=app --network=container:redis -itd feisky/redis-app # [root@local_sa_192-168-1-6 ~]# docker ps CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES fb2709a1ba1e feisky/redis-app "python /app.py" 2 minutes ago Up 15 seconds app 2d1811589334 feisky/redis-server "docker-entrypoint.s…" 4 minutes ago Up 4 minutes 6379/tcp, 0.0.0.0:10000->80/tcp, :::10000->80/tcp redis
-
在客戶端，使用curl工具測試
# 看到hello redis的輸出，說明應用正常啟動 [root@local_deploy_192-168-1-5 ~]# curl http://192.168.1.6:10000/ hello redis # 呼叫應用的/init介面，初始化Redis快取，並且插入5000條快取資訊 # 案例插入5000條資料，在實踐時可以根據磁碟的型別適當調整 [root@local_deploy_192-168-1-5 ~]# curl http://192.168.1.6:10000/init/5000 # 訪問應用的快取查詢介面 [root@local_deploy_192-168-1-5 ~]# curl http://192.168.1.6:10000/get_cache {"count":1677,"data":["d97662fa-06ac-11e9-92c7-0242ac110002",...],"elapsed_seconds":10.5} ## 這個介面呼叫居然要花10秒！這麼長的響應時間，顯然不能滿足實際的應用需求 # 為了避免分析過程中客戶端的請求結束 [root@local_deploy_192-168-1-5 ~]# while true;do curl http://192.168.1.6:10000/get_cache; done
-
在服務端，執行top命令
[root@local_sa_192-168-1-6 ~]# top top - 12:46:18 up 11 days, 8:49, 1 user, load average: 1.36, 1.36, 1.04 Tasks: 137 total, 1 running, 79 sleeping, 0 stopped, 0 zombie %Cpu0 : 6.0 us, 2.7 sy, 0.0 ni, 5.7 id, 84.7 wa, 0.0 hi, 1.0 si, 0.0 st %Cpu1 : 1.0 us, 3.0 sy, 0.0 ni, 94.7 id, 0.0 wa, 0.0 hi, 1.3 si, 0.0 st KiB Mem : 8169300 total, 7342244 free, 432912 used, 394144 buff/cache KiB Swap: 0 total, 0 free, 0 used. 7478748 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 9181 root 20 0 193004 27304 8716 S 8.6 0.3 0:07.15 python 24428 systemd+ 20 0 28352 9760 1860 D 5.0 0.1 0:04.34 redis-server ## 觀察top的輸出可以發現，CPU0的iowait比較高，已經達到了84% 而各個程序的CPU使用率都不太高 最高的python和redis-server，也分別只有8%和5% 再看記憶體，顯然記憶體也沒啥問題 ## 綜合top的資訊，最有嫌疑的就是iowait
-
在服務端，執行iostat命令
[root@local_sa_192-168-1-6 ~]# iostat -d -x 1 Linux 5.15.7-1.el7.elrepo.x86_64 (local_sa_192-168-1-6) 2021年12月22日 _x86_64_ (2 CPU) Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.04 0.42 2.11 1.12 1808.76 159.83 1215.80 0.04 11.40 8.79 16.32 8.33 2.70 scd0 0.00 0.00 0.00 0.00 0.00 0.00 0.33 0.00 0.11 0.11 0.00 0.56 0.00 dm-0 0.00 0.00 0.85 1.19 1808.70 160.14 1925.44 0.07 33.17 20.18 42.44 8.44 1.73 dm-1 0.00 0.00 0.00 0.00 0.01 0.00 51.80 0.00 32.79 32.79 0.00 19.53 0.00 ## 觀察iostat的輸出發現，磁碟sda每秒的寫資料（wkB/s）為159KB I/O 使用率（%util）是0 雖然有些I/O操作，但並沒導致磁碟的I/O瓶頸
-
在服務端，執行pidstat命令
[root@local_sa_192-168-1-6 ~]# pidstat -d 1 Linux 5.15.7-1.el7.elrepo.x86_64 (local_sa_192-168-1-6) 2021年12月22日 _x86_64_ (2 CPU) 14時47分07秒 UID PID kB_rd/s kB_wr/s kB_ccwr/s Command 14時47分08秒 100 24428 0.00 178.22 0.00 redis-server 14時47分08秒 UID PID kB_rd/s kB_wr/s kB_ccwr/s Command 14時47分09秒 100 24428 0.00 180.00 0.00 redis-server 14時47分09秒 UID PID kB_rd/s kB_wr/s kB_ccwr/s Command 14時47分10秒 100 24428 0.00 172.00 0.00 redis-server 平均時間: UID PID kB_rd/s kB_wr/s kB_ccwr/s Command 平均時間: 100 24428 0.00 186.59 0.00 redis-server ## 從pidstat的輸出看到，I/O最多的程序是PID為24428的redis-server 並且它也剛好是在寫磁碟，這說明確實是redis-server在進行磁碟寫
-
在服務端，執行strace和lsof命令
# -f 表示跟蹤子程序和子執行緒 # -T 表示顯示系統呼叫的時長 # -tt 表示顯示跟蹤時間 [root@local_sa_192-168-1-6 ~]# strace -f -T -tt -p 24428 [pid 24428] 14:47:35.448140 epoll_pwait(5, [{EPOLLIN, {u32=8, u64=8}}], 10128, 52, NULL, 8) = 1 <0.000142> [pid 24428] 14:47:35.448421 read(8, "*2\r\n$3\r\nGET\r\n$41\r\nuuid:6c9c7502-"..., 16384) = 61 <0.000072> [pid 24428] 14:47:35.449600 read(3, 0x7fffabf2d427, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000070> [pid 24428] 14:47:35.449812 write(8, "$4\r\ngood\r\n", 10) = 10 <0.000089> ...... [pid 24428] 14:47:35.450204 epoll_pwait(5, [{EPOLLIN, {u32=8, u64=8}}], 10128, 49, NULL, 8) = 1 <0.000164> [pid 24428] 14:47:35.450512 read(8, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n6c9"..., 16384) = 67 <0.000083> [pid 24428] 14:47:35.451660 read(3, 0x7fffabf2d427, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000066> [pid 24428] 14:47:35.451839 write(7, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n6c9"..., 67) = 67 <0.000073> [pid 24428] 14:47:35.451839 fdatasync(7) = 0 <0.005415> ...... ## 從系統呼叫來看，epoll_pwait、read、write、fdatasync這些系統呼叫都比較頻繁 那麼，剛才觀察到的寫磁碟，應該就是write或者fdatasync導致的了 ## lsof [root@local_sa_192-168-1-6 ~]# lsof -p 24428 ...... redis-ser 24428 100 3r FIFO 0,13 0t0 124969 pipe redis-ser 24428 100 4w FIFO 0,13 0t0 124969 pipe redis-ser 24428 100 5u a_inode 0,14 0 8460 [eventpoll] redis-ser 24428 100 6u sock 0,8 0t0 124970 protocol: TCP redis-ser 24428 100 7w REG 253,0 948344 176182428 /data/appendonly.aof redis-ser 24428 100 8u sock 0,8 0t0 126166 protocol: TCP ## 描述符編號為3的是一個pipe管道 5號是eventpoll 7號是一個普通檔案 8號是一個TCP socket ## 結合磁碟寫的現象，只有7號普通檔案才會產生磁碟寫 而它操作的檔案路徑是/data/appendonly.aof 相應的系統呼叫包括write和fdatasync ## redis基礎知識 Redis持久化配置中有appendonly和appendfsync選項 很可能是因為它們的配置不合理，導致磁碟寫比較多
-
在服務端，檢視redis配置
[root@local_sa_192-168-1-6 ~]# docker exec -it redis redis-cli config get 'append*' 1) "appendfsync" 2) "always" 3) "appendonly" 4) "yes" ## appendfsync配置的是always appendonly配置的是yes ######## # Redis提供了兩種資料持久化的方式，分別是快照和追加檔案 1. 快照方式，會按照指定的時間間隔，生成資料的快照，並且儲存到磁碟檔案中。 為了避免阻塞主程序，Redis還會fork出一個子程序，來負責快照的儲存。 這種方式的效能好，無論是備份還是恢復，都比追加檔案好很多 不過，它的缺點也很明顯 在資料量大時，fork子程序需要用到比較大的記憶體，儲存資料也很耗時 所以，需要設定一個比較長的時間間隔來應對，比如至少5分鐘 這樣，如果發生故障，丟失的就是幾分鐘的資料 2. 追加檔案，則是用在檔案末尾追加記錄的方式，對Redis寫入的資料，依次進行持久化，所以它的持久化也更安全 此外，它還提供了一個用appendfsync選項設定fsync的策略，確保寫入的資料都落到磁碟中 具體選項包括always、everysec、no等 always表示，每個操作都會執行一次fsync，是最為安全的方式 everysec表示，每秒鐘呼叫一次fsync，這樣可以保證即使是最壞情況下，也只丟失1秒的資料 no表示，交給作業系統來處理 ######## 案例中appendfsync配置的是always，意味著每次寫資料時，都會呼叫一次fsync，從而造成比較大的磁碟I/O壓力
-
在服務端，執行strace命令，檢視系統呼叫的執行情況
[root@local_sa_192-168-1-6 ~]# strace -f -p 24428 -T -tt -e fdatasync [pid 24428] 14:50:09.346201 fdatasync(7) = 0 <0.022991> [pid 24428] 14:50:09.373546 fdatasync(7) = 0 <0.020661> [pid 24428] 14:50:09.396243 fdatasync(7) = 0 <0.015645> [pid 24428] 14:50:09.416852 fdatasync(7) = 0 <0.019023> [pid 24428] 14:50:09.441939 fdatasync(7) = 0 <0.011531> [pid 24428] 14:50:09.455621 fdatasync(7) = 0 <0.021865> [pid 24428] 14:50:09.479623 fdatasync(7) = 0 <0.022748> [pid 24428] 14:50:09.506912 fdatasync(7) = 0 <0.013260> [pid 24428] 14:50:09.523493 fdatasync(7) = 0 <0.020520> [pid 24428] 14:50:09.548724 fdatasync(7) = 0 <0.020336> [pid 24428] 14:50:09.571242 fdatasync(7) = 0 <0.022781> [pid 24428] 14:50:09.596195 fdatasync(7) = 0 <0.015596> [pid 24428] 14:50:09.616554 fdatasync(7) = 0 <0.027589> [pid 24428] 14:50:09.648494 fdatasync(7) = 0 <0.020671> [pid 24428] 14:50:09.671379 fdatasync(7) = 0 <0.022808> [pid 24428] 14:50:09.696326 fdatasync(7) = 0 <0.015559> [pid 24428] 14:50:09.715756 fdatasync(7) = 0 <0.019982> [pid 24428] 14:50:09.744767 fdatasync(7) = 0 <0.082734> [pid 24428] 14:50:09.830990 fdatasync(7) = 0 <0.023048> [pid 24428] 14:50:09.857060 fdatasync(7) = 0 <0.013441> [pid 24428] 14:50:09.872742 fdatasync(7) = 0 <0.014465> ## 呼叫非常頻繁 ## 找出了Redis正在進行寫入的檔案，也知道了產生大量I/O的原因 ## 為什麼查詢時會有磁碟寫呢？按理來說不應該只有資料的讀取嗎？ [root@local_sa_192-168-1-6 ~]# strace -f -T -tt -p 24428 read(8, "*2\r\n$3\r\nGET\r\n$41\r\nuuid:53522908-"..., 16384) write(8, "$4\r\ngood\r\n", 10) read(8, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n535"..., 16384) write(7, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n535"..., 67) write(8, ":1\r\n", 4) ## 根據lsof的分析，檔案描述符編號為7的是一個普通檔案/data/appendonly.aof 編號為8的是TCP socket 觀察上面的內容，8號對應的TCP讀寫，是一個標準的“請求-響應”格式，即 從socket讀取GET uuid:53522908-… 後，響應good 再從socket讀取SADD good 535… 後，響應1 ## 對Redis來說，SADD是一個寫操作，所以Redis還會把它儲存到用於持久化的appendonly.aof檔案中 觀察更多的strace結果發現，每當GET返回good時，隨後都會有一個SADD操作 這也就導致了，明明是查詢介面，Redis卻有大量的磁碟寫 到這裡就找出了Redis寫磁碟的原因 ### 可以給lsof命令加上-i選項，找出TCP socket對應的TCP連線資訊 不過，由於Redis和Python應用都在容器中執行 需要進入容器的網路名稱空間內部，才能看到完整的TCP連線 nsenter工具，可以進入容器名稱空間
-
在服務端，執行nsenter工具
# 如果系統沒有安裝，請執行下面命令安裝nsenter [root@local_sa_192-168-1-6 ~]# docker run --rm -v /usr/local/bin:/target jpetazzo/nsenter # 由於這兩個容器共享同一個網路名稱空間，所以只需要進入app的網路名稱空間即可 [root@local_sa_192-168-1-6 ~]# PID=$(docker inspect --format {{.State.Pid}} app) # -i 表示顯示網路套接字資訊 [root@local_sa_192-168-1-6 ~]# nsenter --target $PID --net -- lsof -i COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME lsof: no pwd entry for UID 100 redis-ser 24428 100 6u IPv4 124970 0t0 TCP localhost:6379 (LISTEN) lsof: no pwd entry for UID 100 redis-ser 24428 100 8u IPv4 126166 0t0 TCP localhost:6379->localhost:35994 (ESTABLISHED) python 24623 root 3u IPv4 125178 0t0 TCP *:http (LISTEN) python 24623 root 4u IPv4 129547 0t0 TCP local_sa_192-168-1-6:http->192.168.1.5:42294 (ESTABLISHED) python 24623 root 5u IPv4 126165 0t0 TCP localhost:35994->localhost:6379 (ESTABLISHED) ## 這次可以看到，redis-server的8號檔案描述符，對應TCP連線 localhost:6379->localhost:35994 其中，localhost:6379是redis-server自己的監聽埠，自然localhost:35994就是redis的客戶端 再觀察最後一行，localhost:35994對應的，正是Python應用程式（程序號為24623）
-
2個問題
第一個問題，Redis配置的appendfsync是always，這就導致Redis每次的寫操作，都會觸發fdatasync系統呼叫 今天的案例，沒必要用這麼高頻的同步寫，使用預設的1s時間間隔，就足夠了 第二個問題，Python應用在查詢介面中會呼叫Redis的SADD命令，這很可能是不合理使用快取導致的 ## 解決辦法 # 1. 對於第一個配置問題，可以執行下面的命令把appendfsync改成everysec [root@local_sa_192-168-1-6 ~]# docker exec -it redis redis-cli config set appendfsync everysec ## 改完後會發現，現在的請求時間已經縮短到了0.9秒 # 2. 第二個問題，就要檢視應用的原始碼了 [root@local_sa_192-168-1-6 ~]# docker cp app:/app.py . [root@local_sa_192-168-1-6 ~]# cat app.py #!/usr/bin/env python # -*- coding: UTF-8 -*- from functools import wraps from time import time import json import random import uuid import redis from flask import Flask, jsonify app = Flask(__name__) redis_client = redis.StrictRedis( host="127.0.0.1", charset="utf-8", port=6379, db=0, decode_responses=True) def timing(f): '''wrapper for elapsed_seconds''' @wraps(f) def wrapper(*args, **kwargs): start = time() result = f(*args, **kwargs) end = time() data = json.loads(result.get_data()) data["elapsed_seconds"] = end-start return jsonify(data) return wrapper @app.route('/') def hello_world(): '''handler for /''' return 'hello redis\n' @app.route('/get_cache', defaults={'type_name': 'good'}) @app.route("/get_cache/<type_name>") @timing def get_cache(type_name): '''handler for /get_cache''' for key in redis_client.scan_iter("uuid:*"): value = redis_client.get(key) if value == type_name: redis_client.sadd(type_name, key[5:]) data = list(redis_client.smembers(type_name)) redis_client.delete(type_name) return jsonify({"type": type_name, 'count': len(data), 'data': data}) @app.route('/get_cache_data', defaults={'type_name': 'good'}) @app.route("/get_cache_data/<type_name>") @timing def get_cache_data(type_name): '''handler for /get_cache_data''' keys = [key for key in redis_client.scan_iter("uuid:*")] values = redis_client.mget(keys) matched_keys = set([keys[idx][5:] for idx, value in enumerate(values) if value == type_name ]) return jsonify({"type": type_name, 'count': len(matched_keys), 'data': list(matched_keys)}) @app.route('/init', defaults={'num':5000}) @app.route('/init/<num>') @timing def initialize(num): '''handler for /init''' redis_client.flushall() types = ('good', 'bad', 'normal') sample_size = int(num) random_pool = random.sample(range(0, sample_size), sample_size) for i in range(sample_size): key = uuid.uuid1() redis_client.set('uuid:{}'.format(key), types[(random_pool[i]+i) % 3]) return jsonify({"keys_initialized": sample_size}) if __name__ == '__main__': app.run(host='0.0.0.0', port=80) ## 果然，Python應用把Redis當成臨時空間，用來儲存查詢過程中找到的資料 這些資料放記憶體中就可以了，完全沒必要再通過網路呼叫儲存到Redis中 ## 這個介面把查詢過程中產生的資料直接儲存在記憶體了 http://192.168.1.6:10000/get_cache_data
小結
Redis快取的案例
先用top、iostat ，分析了系統的CPU 、記憶體和磁碟使用情況
不過卻發現，系統資源並沒有出現瓶頸
這個時候想要進一步分析的話，該從哪個方向著手呢？
通過今天的案例發現，為了進一步分析，就需要對系統和應用程式的工作原理有一定的瞭解
比如，今天的案例中，雖然磁碟I/O並沒有出現瓶頸，但從Redis的原理來說，查詢快取時不應該出現大量的磁碟I/O寫操作
順著這個思路，繼續借助pidstat、strace、lsof、nsenter等一系列的工具
找出了兩個潛在問題
一個是Redis的不合理配置
另一個是Python應用對Redis的濫用
找到瓶頸後，相應的優化工作自然就比較輕鬆了
轉載請註明出處喲~ https://www.cnblogs.com/lichengguo