文章來源：linux性能優(yōu)化實戰(zhàn)
redis 是最常用的鍵值存儲系統(tǒng)之一，常用作數據庫、高速緩存和消息隊列代理等。Redis 基于內存來存儲數據，不過，為了保證在服務器異常時數據不丟失，很多情況下，我們要為它配置持久化，而這就可能會引發(fā)磁盤 I/O 的性能問題。
今天，我就帶你一起來分析一個利用 Redis 作為緩存的案例。
這同樣是一個基于 Python Flask 的應用程序，它提供了一個 查詢緩存的接口，但接口的響應時間比較長，并不能滿足線上系統(tǒng)的要求。
非常感謝攜程系統(tǒng)研發(fā)部資深后端工程師董國星，幫助提供了今天的案例。
案例準備
本次案例還是基于 Ubuntu 18.04，同樣適用于其他的 Linux 系統(tǒng)。我使用的案例環(huán)境如下所示：
機器配置：2 CPU，8GB 內存
預先安裝 Docker、sysstat 、git、make 等工具，如 apt install docker.io sysstat
今天的案例由 Python 應用 +Redis 兩部分組成。其中，Python 應用是一個基于 Flask 的應用，它會利用 Redis ，來管理應用程序的緩存，并對外提供三個 HTTP 接口：
/：返回 hello redis；
/init/：插入指定數量的緩存數據，如果不指定數量，默認的是 5000 條；
緩存的鍵格式為 uuid:
緩存的值為 good、bad 或 normal 三者之一
/get_cache/<type_name>：查詢指定值的緩存數據，并返回處理時間。其中，type_name 參數只支持 good, bad 和 normal（也就是找出具有相同 value 的 key 列表）。
由于應用比較多，為了方便你運行，我把它們打包成了兩個 Docker 鏡像，并推送到了 Github 上。這樣你就只需要運行幾條命令，就可以啟動了。
今天的案例需要兩臺虛擬機，其中一臺用作案例分析的目標機器，運行 Flask 應用，它的 IP 地址是 192.168.0.10；而另一臺作為客戶端，請求緩存查詢接口。我畫了一張圖來表示它們的關系。
接下來，打開兩個終端，分別 SSH 登錄到這兩臺虛擬機中，并在第一臺虛擬機中安裝上述工具。
跟以前一樣，案例中所有命令都默認以 root 用戶運行，如果你是用普通用戶身份登陸系統(tǒng)，請運行 sudo su root 命令切換到 root 用戶。
到這里，準備工作就完成了。接下來，我們正式進入操作環(huán)節(jié)。
案例分析
首先，我們在第一個終端中，執(zhí)行下面的命令，運行本次案例要分析的目標應用。正常情況下，你應該可以看到下面的輸出：
$ docker run
ec41cb9e4dd5cb7079e1d9f72b7cee7de67278dbd3bd0956b4c0846bff211803
然后，再運行 docker ps 命令，確認兩個容器都處于運行（Up）狀態(tài)：
$ docker ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
2c54eb252d05 feisky/redis-App "python /app.py" 48 seconds ago Up 47 seconds app
ec41cb9e4dd5 feisky/redis-server "docker-entrypoint.s…" 49 seconds ago Up 48 seconds 6379/tcp, 0.0.0.0:10000->80/tcp redis
比如，我們切換到第二個終端，使用 curl 工具，訪問應用首頁。如果你看到 hello redis 的輸出，說明應用正常啟動：
接下來，繼續(xù)在終端二中，執(zhí)行下面的 curl 命令，來調用應用的 /init 接口，初始化 Redis 緩存，并且插入 5000 條緩存信息。這個過程比較慢，比如我的機器就花了十幾分鐘時間。耐心等一會兒后，你會看到下面這行輸出：
# 案例插入5000條數據，在實踐時可以根據磁盤的類型適當調整，比如使用SSD時可以調大，而HDD可以適當調小
$ curl http:
{"elapsed_seconds":30.26814079284668,"keys_initialized":5000}
繼續(xù)執(zhí)行下一個命令，訪問應用的緩存查詢接口。如果一切正常，你會看到如下輸出：
$ curl http:
{"count":1677,"data":["d97662fa-06ac-11e9-92c7-0242ac110002",...],"elapsed_seconds":10.545469760894775,"type":"good"}
我們看到，這個接口調用居然要花 10 秒！這么長的響應時間，顯然不能滿足實際的應用需求。
到底出了什么問題呢？我們還是要用前面學過的性能工具和原理，來找到這個瓶頸。
不過別急，同樣為了避免分析過程中客戶端的請求結束，在進行性能分析前，
我們先要把 curl 命令放到一個循環(huán)里來執(zhí)行。你可以在終端二中，繼續(xù)執(zhí)行下面的命令：
$ while true; do curl http:
接下來，再重新回到終端一，查找接口響應慢的“病因”。
最近幾個案例的現象都是響應很慢，這種情況下，我們自然先會懷疑，是不是系統(tǒng)資源出現了瓶頸。
所以，先觀察 CPU、內存和磁盤 I/O 等的使用情況肯定不會錯。
我們先在終端一中執(zhí)行 top 命令，分析系統(tǒng)的 CPU 使用情況：
$ 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
9085 systemd+ 20 0 28352 9760 1860 D 5.0 0.1 0:04.34 redis-server
368 root 20 0 0 0 0 D 1.0 0.0 0:33.88 jbd2/sda1-8
149 root 0 -20 0 0 0 I 0.3 0.0 0:10.63 kworker/0:1H
1549 root 20 0 236716 24576 9864 S 0.3 0.3 91:37.30 python3
觀察 top 的輸出可以發(fā)現，CPU0 的 iowait 比較高，已經達到了 84%；而各個進程的 CPU 使用率都不太高，最高的 python 和 redis-server ，也分別只有 8% 和 5%。再看內存，總內存 8GB，剩余內存還有 7GB 多，顯然內存也沒啥問題。
綜合 top 的信息，最有嫌疑的就是 iowait。所以，接下來還是要繼續(xù)分析，是不是 I/O 問題。
還在第一個終端中，先按下 Ctrl+C，停止 top 命令；然后，執(zhí)行下面的 IOStat 命令，查看有沒有 I/O 性能問題：
$ iostat -d -x 1
Device r/s w/s rkB/s wkB/s rrqm/s wrqm/s %rrqm %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm %util
...
sda 0.00 492.00 0.00 2672.00 0.00 176.00 0.00 26.35 0.00 1.76 0.00 0.00 5.43 0.00 0.00
觀察 iostat 的輸出，
我們發(fā)現，磁盤 sda 每秒的寫數據（wkB/s）為 2.5MB，I/O 使用率（%util）是 0。
看來，雖然有些 I/O 操作，但并沒導致磁盤的 I/O 瓶頸。
排查一圈兒下來，CPU 和內存使用沒問題，I/O 也沒有瓶頸，接下來好像就沒啥分析方向了？
碰到這種情況，還是那句話，反思一下，是不是又漏掉什么有用線索了。
你可以先自己思考一下，從分析對象（案例應用）、系統(tǒng)原理和性能工具這三個方向下功夫，回憶它們的特性，查找現象的異常，再繼續(xù)往下走。
回想一下，今天的案例問題是從 Redis 緩存中查詢數據慢。
對查詢來說，對應的 I/O 應該是磁盤的讀操作，但剛才我們用 iostat 看到的卻是寫操作。
雖說 I/O 本身并沒有性能瓶頸，但這里的磁盤寫也是比較奇怪的。
為什么會有磁盤寫呢？那我們就得知道，到底是哪個進程在寫磁盤。
要知道 I/O 請求來自哪些進程，還是要靠我們的老朋友 pidstat。在終端一中運行下面的 pidstat 命令，觀察進程的 I/O 情況：
$ pidstat -d 1
12:49:35 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
12:49:36 0 368 0.00 16.00 0.00 86 jbd2/sda1-8
12:49:36 100 9085 0.00 636.00 0.00 1 redis-server
從 pidstat 的輸出，我們看到，I/O 最多的進程是 PID 為 9085 的 redis-server，并且它也剛好是在寫磁盤。這說明，確實是 redis-server 在進行磁盤寫。
當然，光找到讀寫磁盤的進程還不夠，我們還要再用 strace+lsof 組合，看看 redis-server 到底在寫什么。
接下來，還是在終端一中，執(zhí)行 strace 命令，并且指定 redis-server 的進程號 9085：
# -f表示跟蹤子進程和子線程，-T表示顯示系統(tǒng)調用的時長，-tt表示顯示跟蹤時間
$ strace -f -T -tt -p 9085
[pid 9085] 14:20:16.826131 epoll_pwait(5, [{EPOLLIN, {u32=8, u64=8}}], 10128, 65, NULL, 8) = 1 <0.000055>
[pid 9085] 14:20:16.826301 read(8, "*2rn$3rnGETrn$41rnuuid:5b2e76cc-"..., 16384) = 61 <0.000071>
[pid 9085] 14:20:16.826477 read(3, 0x7fff366a5747, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000063>
[pid 9085] 14:20:16.826645 write(8, "$3rnbadrn", 9) = 9 <0.000173>
[pid 9085] 14:20:16.826907 epoll_pwait(5, [{EPOLLIN, {u32=8, u64=8}}], 10128, 65, NULL, 8) = 1 <0.000032>
[pid 9085] 14:20:16.827030 read(8, "*2rn$3rnGETrn$41rnuuid:55862ada-"..., 16384) = 61 <0.000044>
[pid 9085] 14:20:16.827149 read(3, 0x7fff366a5747, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000043>
[pid 9085] 14:20:16.827285 write(8, "$3rnbadrn", 9) = 9 <0.000141>
[pid 9085] 14:20:16.827514 epoll_pwait(5, [{EPOLLIN, {u32=8, u64=8}}], 10128, 64, NULL, 8) = 1 <0.000049>
[pid 9085] 14:20:16.827641 read(8, "*2rn$3rnGETrn$41rnuuid:53522908-"..., 16384) = 61 <0.000043>
[pid 9085] 14:20:16.827784 read(3, 0x7fff366a5747, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000034>
[pid 9085] 14:20:16.827945 write(8, "$4rngoodrn", 10) = 10 <0.000288>
[pid 9085] 14:20:16.828339 epoll_pwait(5, [{EPOLLIN, {u32=8, u64=8}}], 10128, 63, NULL, 8) = 1 <0.000057>
[pid 9085] 14:20:16.828486 read(8, "*3rn$4rnSADDrn$4rngoodrn$36rn535"..., 16384) = 67 <0.000040>
[pid 9085] 14:20:16.828623 read(3, 0x7fff366a5747, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000052>
[pid 9085] 14:20:16.828760 write(7, "*3rn$4rnSADDrn$4rngoodrn$36rn535"..., 67) = 67 <0.000060>
[pid 9085] 14:20:16.828970 fdatasync(7) = 0 <0.005415>
[pid 9085] 14:20:16.834493 write(8, ":1rn", 4) = 4 <0.000250>
觀察一會兒，有沒有發(fā)現什么有趣的現象呢？
事實上，從系統(tǒng)調用來看， epoll_pwait、read、write、fdatasync 這些系統(tǒng)調用都比較頻繁。
那么，剛才觀察到的寫磁盤，應該就是 write 或者 fdatasync 導致的了。
接著再來運行 lsof 命令，找出這些系統(tǒng)調用的操作對象：
$ lsof -p 9085
redis-ser 9085 systemd-network 3r FIFO 0,12 0t0 15447970 pipe
redis-ser 9085 systemd-network 4w FIFO 0,12 0t0 15447970 pipe
redis-ser 9085 systemd-network 5u a_inode 0,13 0 10179 [eventpoll]
redis-ser 9085 systemd-network 6u sock 0,9 0t0 15447972 protocol: TCP
redis-ser 9085 systemd-network 7w REG 8,1 8830146 2838532 /data/appendonly.aof
redis-ser 9085 systemd-network 8u sock 0,9 0t0 15448709 protocol: TCP
現在你會發(fā)現，描述符編號為 3 的是一個 pipe 管道，5 號是 eventpoll，7 號是一個普通文件，而 8 號是一個 TCP socket。
結合磁盤寫的現象，我們知道，只有 7 號普通文件才會產生磁盤寫，而它操作的文件路徑是 /data/appendonly.aof，相應的系統(tǒng)調用包括 write 和 fdatasync。
如果你對 Redis 的持久化配置比較熟，看到這個文件路徑以及 fdatasync 的系統(tǒng)調用，你應該能想到，這對應著正是 Redis 持久化配置中的 appendonly 和 appendfsync 選項。很可能是因為它們的配置不合理，導致磁盤寫比較多。
接下來就驗證一下這個猜測，我們可以通過 Redis 的命令行工具，查詢這兩個選項的配置。
繼續(xù)在終端一中，運行下面的命令，查詢 appendonly 和 appendfsync 的配置：
$ docker exec -it redis redis-cli config get 'append*'
1) "appendfsync"
2) "always"
3) "appendonly"
4) "yes"
從這個結果你可以發(fā)現，appendfsync 配置的是 always，而 appendonly 配置的是 yes。
這兩個選項的詳細含義，你可以從 Redis Persistence 的文檔中查到，這里我做一下簡單介紹。
Redis 提供了兩種數據持久化的方式，分別是快照和追加文件。
快照方式，會按照指定的時間間隔，生成數據的快照，并且保存到磁盤文件中。
- 為了避免阻塞主進程，Redis 還會 fork 出一個子進程，來負責快照的保存。這種方式的性能好，無論是備份還是恢復，都比追加文件好很多。
不過，它的缺點也很明顯。在數據量大時，fork 子進程需要用到比較大的內存，保存數據也很耗時。所以，你需要設置一個比較長的時間間隔來應對，比如至少 5 分鐘。這樣，如果發(fā)生故障，你丟失的就是幾分鐘的數據。
- 追加文件，則是用在文件末尾追加記錄的方式，對 Redis 寫入的數據，依次進行持久化，所以它的持久化也更安全。
此外，它還提供了一個用 appendfsync 選項設置 fsync 的策略，確保寫入的數據都落到磁盤中，具體選項包括 always、everysec、no 等。
- always 表示，每個操作都會執(zhí)行一次 fsync，是最為安全的方式；
- everysec 表示，每秒鐘調用一次 fsync ，這樣可以保證即使是最壞情況下，也只丟失 1 秒的數據；
- 而 no 表示交給操作系統(tǒng)來處理。
回憶一下我們剛剛看到的配置，appendfsync 配置的是 always，意味著每次寫數據時，都會調用一次 fsync，從而造成比較大的磁盤 I/O 壓力。
當然，你還可以用 strace ，觀察這個系統(tǒng)調用的執(zhí)行情況。比如通過 -e 選項指定 fdatasync 后，你就會得到下面的結果：
$ strace -f -p 9085 -T -tt -e fdatasync
strace: Process 9085 attached with 4 threads
[pid 9085] 14:22:52.013547 fdatasync(7) = 0 <0.007112>
[pid 9085] 14:22:52.022467 fdatasync(7) = 0 <0.008572>
[pid 9085] 14:22:52.032223 fdatasync(7) = 0 <0.006769>
...
從這里你可以看到，每隔 10ms 左右，就會有一次 fdatasync 調用，并且每次調用本身也要消耗 7~8ms。
不管哪種方式，都可以驗證我們的猜想，配置確實不合理。這樣，我們就找出了 Redis 正在進行寫入的文件，也知道了產生大量 I/O 的原因。
不過，回到最初的疑問，為什么查詢時會有磁盤寫呢？按理來說不應該只有數據的讀取嗎？這就需
要我們再來審查一下 strace -f -T -tt -p 9085 的結果。
read(8, "*2rn$3rnGETrn$41rnuuid:53522908-"..., 16384)
write(8, "$4rngoodrn", 10)
read(8, "*3rn$4rnSADDrn$4rngoodrn$36rn535"..., 16384)
write(7, "*3rn$4rnSADDrn$4rngoodrn$36rn535"..., 67)
write(8, ":1rn", 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 結果，你會發(fā)現，每當 GET 返回 good 時，隨后都會有一個 SADD 操作，這也就導致了，明明是查詢接口，Redis 卻有大量的磁盤寫。
到這里，我們就找出了 Redis 寫磁盤的原因。不過，在下最終結論前，我們還是要確認一下，8 號 TCP socket 對應的 Redis 客戶端，到底是不是我們的案例應用。
我們可以給 lsof 命令加上 -i 選項，找出 TCP socket 對應的 TCP 連接信息。不過，由于 Redis 和 Python 應用都在容器中運行，我們需要進入容器的網絡命名空間內部，才能看到完整的 TCP 連接。
注意：下面的命令用到的 nsenter 工具，可以進入容器命名空間。如果你的系統(tǒng)沒有安裝，請運行下面命令安裝 nsenter：
docker run --rm -v /usr/local/bin:/target jpetazzo/nsenter
還是在終端一中，運行下面的命令：
# 由于這兩個容器共享同一個網絡命名空間，所以我們只需要進入app的網絡命名空間即可
$ PID=$(docker inspect --format {{.State.Pid}} app)
# -i表示顯示網絡套接字信息
$ nsenter --target $PID --net -- lsof -i
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
redis-ser 9085 systemd-network 6u IPv4 15447972 0t0 TCP localhost:6379 (LISTEN)
redis-ser 9085 systemd-network 8u IPv4 15448709 0t0 TCP localhost:6379->localhost:32996 (ESTABLISHED)
python 9181 root 3u IPv4 15448677 0t0 TCP *:http (LISTEN)
python 9181 root 5u IPv4 15449632 0t0 TCP localhost:32996->localhost:6379 (ESTABLISHED)
這次我們可以看到，redis-server 的 8 號文件描述符，對應 TCP 連接 localhost:6379->localhost:32996。
其中， localhost:6379 是 redis-server 自己的監(jiān)聽端口，自然 localhost:32996 就是 redis 的客戶端。
再觀察最后一行，localhost:32996 對應的，正是我們的 Python 應用程序（進程號為 9181）。
歷經各種波折，我們總算找出了 Redis 響應延遲的潛在原因?？偨Y一下，我們找到兩個問題。
第一個問題，Redis 配置的 appendfsync 是 always，這就導致 Redis 每次的寫操作，都會觸發(fā) fdatasync 系統(tǒng)調用。今天的案例，沒必要用這么高頻的同步寫，使用默認的 1s 時間間隔，就足夠了。
第二個問題，Python 應用在查詢接口中會調用 Redis 的 SADD 命令，這很可能是不合理使用緩存導致的。
對于第一個配置問題，我們可以執(zhí)行下面的命令，把 appendfsync 改成 everysec：
$ docker exec -it redis redis-cli config set appendfsync everysec
OK
改完后，切換到終端二中查看，你會發(fā)現，現在的請求時間，已經縮短到了 0.9s：
{..., "elapsed_seconds":0.9368953704833984,"type":"good"}
而第二個問題，就要查看應用的源碼了。點擊 Github ，你就可以查看案例應用的源代碼：
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})
果然，Python 應用把 Redis 當成臨時空間，用來存儲查詢過程中找到的數據。不過我們知道，這些數據放內存中就可以了，完全沒必要再通過網絡調用存儲到 Redis 中。
$ while true; do curl http:
{...,"elapsed_seconds":0.16034674644470215,"type":"good"}
你可以發(fā)現，解決第二個問題后，新接口的性能又有了進一步的提升，從剛才的 0.9s ，再次縮短成了不到 0.2s。
當然，案例最后，不要忘記清理案例應用。你可以切換到終端一中，執(zhí)行下面的命令進行清理：
小結
今天我?guī)阋黄鸱治隽艘粋€ Redis 緩存的案例。
我們先用 top、iostat ，分析了系統(tǒng)的 CPU 、內存和磁盤使用情況，不過卻發(fā)現，系統(tǒng)資源并沒有出現瓶頸。這個時候想要進一步分析的話，該從哪個方向著手呢？
通過今天的案例你會發(fā)現，為了進一步分析，就需要你對系統(tǒng)和應用程序的工作原理有一定的了解。
比如，今天的案例中，雖然磁盤 I/O 并沒有出現瓶頸，但從 Redis 的原理來說，查詢緩存時不應該出現大量的磁盤 I/O 寫操作。
順著這個思路，我們繼續(xù)借助 pidstat、strace、lsof、nsenter 等一系列的工具，找出了兩個潛在問題，一個是 Redis 的不合理配置，另一個是 Python 應用對 Redis 的濫用。找到瓶頸后，相應的優(yōu)化工作自然就比較輕松了。
思考
最后給你留一個思考題。從上一節(jié) MySQL 到今天 Redis 的案例分析，你有沒有發(fā)現 I/O 性能問題的分析規(guī)律呢？如果你有任何想法或心得，都可以記錄下來。
當然，這兩個案例這并不能涵蓋所有的 I/O 性能問題。你在實際工作中，還碰到過哪些 I/O 性能問題嗎？你又是怎么分析的呢？
歡迎在留言區(qū)和我討論，也歡迎把這篇文章分享給你的同事、朋友。我們一起在實戰(zhàn)中演練，在交流中進步。
