29 | 案例篇:Redis響應嚴重延遲,如何解決?
阿新 • • 發佈:2020-11-25
在訪問商品搜尋介面時,我們發現介面的響應特別慢。通過對系統 CPU、記憶體和磁碟 I/O 等資源使用情況的分析,我們發現這時出現了磁碟的 I/O 瓶頸,並且正是案例應用導致的。
接著,我們藉助 pidstat,發現罪魁禍首是 mysqld 程序。我們又通過 strace、lsof,找出了 mysqld 正在讀的檔案。根據檔案的名字和路徑,我們找出了 mysqld 正在操作的資料庫和資料表。綜合這些資訊,我們猜測這是一個沒利用索引導致的慢查詢問題。為了驗證猜測,我們到 MySQL 命令列終端,使用資料庫分析工具發現,案例應用訪問的欄位果然沒有索引。既然猜測是正確的,那增加索引後,問題就自然解決了。從這個案例你會發現,MySQL 的 MyISAM 引擎,主要依賴系統快取加速磁碟 I/O 的訪問。可如果系統中還有其他應用同時執行, MyISAM 引擎很難充分利用系統快取。快取可能會被其他應用程式佔用,甚至被清理掉。所以,一般我並不建議,把應用程式的效能優化完全建立在系統快取上。最好能在應用程式的內部分配記憶體,構建完全自主控制的快取;或者使用第三方的快取應用,比如 Memcached、Redis 等。 Redis 是最常用的鍵值儲存系統之一,常用作資料庫、快取記憶體和訊息佇列代理等。Redis 基於記憶體來儲存資料,不過,為了保證在伺服器異常時資料不丟失,很多情況下,我們要為它配置持久化,而這就可能會引發磁碟 I/O 的效能問題。今天,我就帶你一起來分析一個利用 Redis 作為快取的案例。這同樣是一個基於 Python Flask 的應用程式,它提供了一個查詢快取的介面,但介面的響應時間比較長,並不能滿足線上系統的要求。非常感謝攜程系統研發部資深後端工程師董國星,幫助提供了今天的案例。
今天的案例由 Python 應用 +Redis 兩部分組成。其中,Python 應用是一個基於 Flask 的應用,它會利用 Redis ,來管理應用程式的快取,並對外提供三個 HTTP 介面:
由於應用比較多,為了方便你執行,我把它們打包成了兩個 Docker 映象,並推送到了 上。這樣你就只需要執行幾條命令,就可以啟動了。
今天的案例需要兩臺虛擬機器,其中一臺用作案例分析的目標機器,執行 Flask 應用,它的 IP 地址是 192.168.0.10;而另一臺作為客戶端,請求快取查詢介面。我畫了一張圖來表示它們的關係。
接下來,開啟兩個終端,分別 SSH 登入到這兩臺虛擬機器中,並在第一臺虛擬機器中安裝上述工具。跟以前一樣,案例中所有命令都預設以 root 使用者執行,如果你是用普通使用者身份登陸系統,請執行 sudo su root 命令切換到 root 使用者。到這裡,準備工作就完成了。接下來,我們正式進入操作環節。
快照方式,會按照指定的時間間隔,生成資料的快照,並且儲存到磁碟檔案中。為了避免阻塞主程序,Redis 還會 fork 出一個子程序,來負責快照的儲存。這種方式的效能好,無論是備份還是恢復,都比追加檔案好很多。
不過,它的缺點也很明顯。在資料量大時,fork 子程序需要用到比較大的記憶體,儲存資料也很耗時。所以,你需要設定一個比較長的時間間隔來應對,比如至少 5 分鐘。這樣,如果發生故障,你丟失的就是幾分鐘的資料。
追加檔案,則是用在檔案末尾追加記錄的方式,對 Redis 寫入的資料,依次進行持久化,所以它的持久化也更安全。
此外,它還提供了一個用 appendfsync 選項設定 fsync 的策略,確保寫入的資料都落到磁碟中,具體選項包括 always、everysec、no 等。
當然,你還可以用 strace ,觀察這個系統呼叫的執行情況。比如通過 -e 選項指定 fdatasync 後,你就會得到下面的結果:
對 Redis 來說,SADD 是一個寫操作,所以 Redis 還會把它儲存到用於持久化的 appendonly.aof 檔案中。觀察更多的 strace 結果,你會發現,每當 GET 返回 good 時,隨後都會有一個 SADD 操作,這也就導致了,明明是查詢介面,Redis 卻有大量的磁碟寫。
到這裡,我們就找出了 Redis 寫磁碟的原因。不過,在下最終結論前,我們還是要確認一下,8 號 TCP socket 對應的 Redis 客戶端,到底是不是我們的案例應用。
我們可以給 lsof 命令加上 -i 選項,找出 TCP socket 對應的 TCP 連線資訊。不過,由於 Redis 和 Python 應用都在容器中執行,我們需要進入容器的網路名稱空間內部,才能看到完整的 TCP 連線。
思考最後給你留一個思考題。從上一節 MySQL 到今天 Redis 的案例分析,你有沒有發現 I/O 效能問題的分析規律呢?如果你有任何想法或心得,都可以記錄下來。
接著,我們藉助 pidstat,發現罪魁禍首是 mysqld 程序。我們又通過 strace、lsof,找出了 mysqld 正在讀的檔案。根據檔案的名字和路徑,我們找出了 mysqld 正在操作的資料庫和資料表。綜合這些資訊,我們猜測這是一個沒利用索引導致的慢查詢問題。為了驗證猜測,我們到 MySQL 命令列終端,使用資料庫分析工具發現,案例應用訪問的欄位果然沒有索引。既然猜測是正確的,那增加索引後,問題就自然解決了。從這個案例你會發現,MySQL 的 MyISAM 引擎,主要依賴系統快取加速磁碟 I/O 的訪問。可如果系統中還有其他應用同時執行, MyISAM 引擎很難充分利用系統快取。快取可能會被其他應用程式佔用,甚至被清理掉。所以,一般我並不建議,把應用程式的效能優化完全建立在系統快取上。最好能在應用程式的內部分配記憶體,構建完全自主控制的快取;或者使用第三方的快取應用,比如 Memcached、Redis 等。
案例準備
本次案例還是基於 Ubuntu 18.04,同樣適用於其他的 Linux 系統。我使用的案例環境如下所示:機器配置:2 CPU,8GB 記憶體預先安裝 docker、sysstat 、git、make 等工具,如 apt install docker.io sysstat- /:返回 hello redis;
- /init/:插入指定數量的快取資料,如果不指定數量,預設的是 5000 條;
- 快取的鍵格式為 uuid:
- 快取的值為 good、bad 或 normal 三者之一
- /get_cache/<type_name>:查詢指定值的快取資料,並返回處理時間。其中,type_name 引數只支援 good, bad 和 normal(也就是找出具有相同 value 的 key 列表)。
由於應用比較多,為了方便你執行,我把它們打包成了兩個 Docker 映象,並推送到了 上。這樣你就只需要執行幾條命令,就可以啟動了。
接下來,開啟兩個終端,分別 SSH 登入到這兩臺虛擬機器中,並在第一臺虛擬機器中安裝上述工具。跟以前一樣,案例中所有命令都預設以 root 使用者執行,如果你是用普通使用者身份登陸系統,請執行 sudo su root 命令切換到 root 使用者。到這裡,準備工作就完成了。接下來,我們正式進入操作環節。
案例分析
首先,我們在第一個終端中,執行下面的命令,執行本次案例要分析的目標應用。正常情況下,你應該可以看到下面的輸出:# 注意下面的隨機字串是容器 ID,每次執行均會不同,並且你不需要關注它
$ docker run --name=redis -itd -p 10000:80 feisky/redis-server
ec41cb9e4dd5cb7079e1d9f72b7cee7de67278dbd3bd0956b4c0846bff211803
$ docker run --name=app --network=container:redis -itd feisky/redis-app
2c54eb252d0552448320d9155a2618b799a1e71d7289ec7277a61e72a9de5fd0
然後,再執行 docker ps 命令,確認兩個容器都處於執行(Up)狀態:$ 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
今天的應用在 10000 埠監聽,所以你可以通過 http://192.168.0.10:10000 ,來訪問前面提到的三個介面。比如,我們切換到第二個終端,使用 curl 工具,訪問應用首頁。如果你看到 hello redis 的輸出,說明應用正常啟動:$ curl http://192.168.0.10:10000/
hello redis
接下來,繼續在終端二中,執行下面的 curl 命令,來呼叫應用的 /init 介面,初始化 Redis 快取,並且插入 5000 條快取資訊。這個過程比較慢,比如我的機器就花了十幾分鍾時間。耐心等一會兒後,你會看到下面這行輸出:# 案例插入 5000 條資料,在實踐時可以根據磁碟的型別適當調整,比如使用 SSD 時可以調大,而 HDD 可以適當調小
$ curl http://192.168.0.10:10000/init/5000
{"elapsed_seconds":30.26814079284668,"keys_initialized":5000}
繼續執行下一個命令,訪問應用的快取查詢介面。如果一切正常,你會看到如下輸出:$ curl http://192.168.0.10:10000/get_cache
{"count":1677,"data":["d97662fa-06ac-11e9-92c7-0242ac110002",...],"elapsed_seconds":10.545469760894775,"type":"good"}
我們看到,這個介面呼叫居然要花 10 秒!這麼長的響應時間,顯然不能滿足實際的應用需求。到底出了什麼問題呢?我們還是要用前面學過的效能工具和原理,來找到這個瓶頸。不過別急,同樣為了避免分析過程中客戶端的請求結束,在進行效能分析前,我們先要把 curl 命令放到一個迴圈裡來執行。你可以在終端二中,繼續執行下面的命令:$ while true; do curl http://192.168.0.10:10000/get_cache; done
接下來,再重新回到終端一,查詢介面響應慢的“病因”。最近幾個案例的現象都是響應很慢,這種情況下,我們自然先會懷疑,是不是系統資源出現了瓶頸。所以,先觀察 CPU、記憶體和磁碟 I/O 等的使用情況肯定不會錯。我們先在終端一中執行 top 命令,分析系統的 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 的輸出可以發現,CPU0 的 iowait 比較高,已經達到了 84%;而各個程序的 CPU 使用率都不太高,最高的 python 和 redis-server ,也分別只有 8% 和 5%。再看記憶體,總記憶體 8GB,剩餘記憶體還有 7GB 多,顯然記憶體也沒啥問題。綜合 top 的資訊,最有嫌疑的就是 iowait。所以,接下來還是要繼續分析,是不是 I/O 問題。還在第一個終端中,先按下 Ctrl+C,停止 top 命令;然後,執行下面的 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 的輸出,我們發現,磁碟 sda 每秒的寫資料(wkB/s)為 2.5MB,I/O 使用率(%util)是 0。看來,雖然有些 I/O 操作,但並沒導致磁碟的 I/O 瓶頸。排查一圈兒下來,CPU 和記憶體使用沒問題,I/O 也沒有瓶頸,接下來好像就沒啥分析方向了?碰到這種情況,還是那句話,反思一下,是不是又漏掉什麼有用線索了。你可以先自己思考一下,從分析物件(案例應用)、系統原理和效能工具這三個方向下功夫,回憶它們的特性,查詢現象的異常,再繼續往下走。回想一下,今天的案例問題是從 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 到底在寫什麼。接下來,還是在終端一中,執行 strace 命令,並且指定 redis-server 的程序號 9085:# -f 表示跟蹤子程序和子執行緒,-T 表示顯示系統呼叫的時長,-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, "*2\r\n$3\r\nGET\r\n$41\r\nuuid: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, "$3\r\nbad\r\n", 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, "*2\r\n$3\r\nGET\r\n$41\r\nuuid: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, "$3\r\nbad\r\n", 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, "*2\r\n$3\r\nGET\r\n$41\r\nuuid: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, "$4\r\ngood\r\n", 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, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n535"..., 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, "*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n535"..., 67) = 67 <0.000060>
[pid 9085] 14:20:16.828970 fdatasync(7) = 0 <0.005415>
[pid 9085] 14:20:16.834493 write(8, ":1\r\n", 4) = 4 <0.000250>
觀察一會兒,有沒有發現什麼有趣的現象呢?事實上,從系統呼叫來看, epoll_pwait、read、write、fdatasync 這些系統呼叫都比較頻繁。那麼,剛才觀察到的寫磁碟,應該就是 write 或者 fdatasync 導致的了。接著再來執行 lsof 命令,找出這些系統呼叫的操作物件:$ 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
現在你會發現,描述符編號為 3 的是一個 pipe 管道,5 號是 eventpoll,7 號是一個普通檔案,而 8 號是一個 TCP socket。結合磁碟寫的現象,我們知道,只有 7 號普通檔案才會產生磁碟寫,而它操作的檔案路徑是 /data/appendonly.aof,相應的系統呼叫包括 write 和 fdatasync。如果你對 Redis 的持久化配置比較熟,看到這個檔案路徑以及 fdatasync 的系統呼叫,你應該能想到,這對應著正是 Redis 持久化配置中的 appendonly 和 appendfsync 選項。很可能是因為它們的配置不合理,導致磁碟寫比較多。接下來就驗證一下這個猜測,我們可以通過 Redis 的命令列工具,查詢這兩個選項的配置。繼續在終端一中,執行下面的命令,查詢 appendonly 和 appendfsync 的配置:$ docker exec -it redis redis-cli config get 'append*'
1) "appendfsync"
2) "always"
3) "appendonly"
4) "yes"
從這個結果你可以發現,appendfsync 配置的是 always,而 appendonly 配置的是 yes。這兩個選項的詳細含義,你可以從 Redis Persistence 的文件中查到,這裡我做一下簡單介紹。資料持久化
Redis 提供了兩種資料持久化的方式,分別是快照和追加檔案。快照方式,會按照指定的時間間隔,生成資料的快照,並且儲存到磁碟檔案中。為了避免阻塞主程序,Redis 還會 fork 出一個子程序,來負責快照的儲存。這種方式的效能好,無論是備份還是恢復,都比追加檔案好很多。
不過,它的缺點也很明顯。在資料量大時,fork 子程序需要用到比較大的記憶體,儲存資料也很耗時。所以,你需要設定一個比較長的時間間隔來應對,比如至少 5 分鐘。這樣,如果發生故障,你丟失的就是幾分鐘的資料。
追加檔案,則是用在檔案末尾追加記錄的方式,對 Redis 寫入的資料,依次進行持久化,所以它的持久化也更安全。
此外,它還提供了一個用 appendfsync 選項設定 fsync 的策略,確保寫入的資料都落到磁碟中,具體選項包括 always、everysec、no 等。
- always 表示,每個操作都會執行一次 fsync,是最為安全的方式;
- everysec 表示,每秒鐘呼叫一次 fsync ,這樣可以保證即使是最壞情況下,也只丟失 1 秒的資料;
- 而 no 表示交給作業系統來處理。
當然,你還可以用 strace ,觀察這個系統呼叫的執行情況。比如通過 -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>
...
[pid 9085] 14:22:52.139629 fdatasync(7) = 0 <0.008183>
從這裡你可以看到,每隔 10ms 左右,就會有一次 fdatasync 呼叫,並且每次呼叫本身也要消耗 7~8ms。不管哪種方式,都可以驗證我們的猜想,配置確實不合理。這樣,我們就找出了 Redis 正在進行寫入的檔案,也知道了產生大量 I/O 的原因。不過,回到最初的疑問,為什麼查詢時會有磁碟寫呢?按理來說不應該只有資料的讀取嗎?這就需要我們再來審查一下 strace -f -T -tt -p 9085 的結果。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 寫磁碟的原因。不過,在下最終結論前,我們還是要確認一下,8 號 TCP socket 對應的 Redis 客戶端,到底是不是我們的案例應用。
我們可以給 lsof 命令加上 -i 選項,找出 TCP socket 對應的 TCP 連線資訊。不過,由於 Redis 和 Python 應用都在容器中執行,我們需要進入容器的網路名稱空間內部,才能看到完整的 TCP 連線。
nsenter
注意:下面的命令用到的 nsenter 工具,可以進入容器名稱空間。如果你的系統沒有安裝,請執行下面命令安裝 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 自己的監聽埠,自然 localhost:32996 就是 redis 的客戶端。再觀察最後一行,localhost:32996 對應的,正是我們的 Python 應用程式(程序號為 9181)。歷經各種波折,我們總算找出了 Redis 響應延遲的潛在原因。總結一下,我們找到兩個問題。- 第一個問題,Redis 配置的 appendfsync 是 always,這就導致 Redis 每次的寫操作,都會觸發 fdatasync 系統呼叫。今天的案例,沒必要用這麼高頻的同步寫,使用預設的 1s 時間間隔,就足夠了。
- 第二個問題,Python 應用在查詢介面中會呼叫 Redis 的 SADD 命令,這很可能是不合理使用快取導致的。
$ docker exec -it redis redis-cli config set appendfsync everysec
OK
改完後,切換到終端二中檢視,你會發現,現在的請求時間,已經縮短到了 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 中。基於這個思路,我把修改後的程式碼也推送到了相同的原始碼檔案中,你可以通過 http://192.168.0.10:10000/get_cache_data 這個介面來訪問它。我們切換到終端二,按 Ctrl+C 停止之前的 curl 命令;然後執行下面的 curl 命令,呼叫 http://192.168.0.10:10000/get_cache_data 新介面:$ while true; do curl http://192.168.0.10:10000/get_cache_data; done
{...,"elapsed_seconds":0.16034674644470215,"type":"good"}
你可以發現,解決第二個問題後,新介面的效能又有了進一步的提升,從剛才的 0.9s ,再次縮短成了不到 0.2s。當然,案例最後,不要忘記清理案例應用。你可以切換到終端一中,執行下面的命令進行清理:$ docker rm -f app redis
小結
今天我帶你一起分析了一個 Redis 快取的案例。我們先用 top、iostat ,分析了系統的 CPU 、記憶體和磁碟使用情況,不過卻發現,系統資源並沒有出現瓶頸。這個時候想要進一步分析的話,該從哪個方向著手呢?通過今天的案例你會發現,為了進一步分析,就需要你對系統和應用程式的工作原理有一定的瞭解。比如,今天的案例中,雖然磁碟 I/O 並沒有出現瓶頸,但從 Redis 的原理來說,查詢快取時不應該出現大量的磁碟 I/O 寫操作。順著這個思路,我們繼續借助 pidstat、strace、lsof、nsenter 等一系列的工具,找出了兩個潛在問題,一個是 Redis 的不合理配置,另一個是 Python 應用對 Redis 的濫用。找到瓶頸後,相應的優化工作自然就比較輕鬆了。思考最後給你留一個思考題。從上一節 MySQL 到今天 Redis 的案例分析,你有沒有發現 I/O 效能問題的分析規律呢?如果你有任何想法或心得,都可以記錄下來。