1.文件系統和磁盤的 IO 問題的分析（如何找出狂打日志的“內鬼”？）
預先安裝 docker、sysstat 等工具，如 apt install docker.io sysstat
安裝losf：yum install lsof
安裝iostat:：yum install iostat
1.我們在終端中執行下面的命令，運行今天的目標應用：
$ docker run -v /tmp:/tmp --name=app -itd feisky/logapp
|
2.然后，在終端中運行 ps 命令，確認案例應用正常啟動。如果操作無誤，你應該可以在 ps 的輸出中，看到一個 app.py 的進程：
ps -ef | grep /app.py
root
10805
10774
42
02
:
04
pts/
0
00
:
07
:
04
python /app.py
|
可以先用 top ，來觀察 CPU 和內存的使用情況；然后再用 iostat ，來觀察磁盤的 I/O 情況。
3.接下來，你可以在終端中運行 top 命令，觀察 CPU 和內存的使用情況：
top -
10
:
35
:
04
up
268
days,
19
:
53
,
2
users, load average:
3.00
,
3.10
,
2.85
Tasks:
169
total,
1
running,
168
sleeping,
0
stopped,
0
zombie
Cpu0 :
0.3
%us,
1.3
%sy,
0.0
%ni,
0.0
%id,
98.3
%wa,
0.0
%hi,
0.0
%si,
0.0
%st
Cpu1 :
2.0
%us,
1.3
%sy,
0.0
%ni,
96.7
%id,
0.0
%wa,
0.0
%hi,
0.0
%si,
0.0
%st
Cpu2 :
0.0
%us,
0.0
%sy,
0.0
%ni,
73.9
%id,
26.1
%wa,
0.0
%hi,
0.0
%si,
0.0
%st
Cpu3 :
14.3
%us,
43.3
%sy,
0.0
%ni,
6.7
%id,
35.7
%wa,
0.0
%hi,
0.0
%si,
0.0
%st
Mem: 8061128k total, 4679996k used, 3381132k free, 294232k buffers
Swap: 0k total, 0k used, 0k free, 2683132k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
30989
root
20
0
940m 910m
3304
D
57.8
11.6
4
:
59.60
python
5918
root
20
0
2146m 59m
1984
S
1.7
0.7
1713
:
02
python3
522
root
20
0
0
0
0
D
1.3
0.0
6
:
03.57
flush-
252
:
0
1274
root
20
0
2449m 69m
2672
S
1.3
0.9
2037
:
04
java
|
觀察 top 的輸出，你會發現，CPU 的使用率非常高，它的系統 CPU 使用率（sys%）為 1.3%，而 iowait 超過了 98%。這說明 CPU0上，可能正在運行 I/O 密集型的進程。不過，究竟是什么原因呢？這個疑問先保留着，我們先繼續看完。
接着我們來看，進程部分的 CPU 使用情況。你會發現， python 進程的 CPU 使用率已經達到了 57%，而其余進程的 CPU 使用率都比較低。看起來 python 是個可疑進程。記下 python 進程的 PID 號 30989，我們稍后分析。
最后再看內存的使用情況，總內存 8G，剩余內存有4G，而 Buffer/Cache 占用內存高達 2GB 之多，這說明內存主要被緩存占用。雖然大部分緩存可回收，我們還是得了解下緩存的去處，確認緩存使用都是合理的。
到這一步，你基本可以判斷出，CPU 使用率中的 iowait 是一個潛在瓶頸，而內存部分的緩存占比較大，那磁盤 I/O 又是怎么樣的情況呢？
4.運行 iostat 命令，觀察 I/O 的使用情況：
# -d 表示顯示 I/O 性能指標，-x 表示顯示擴展統計（即所有 I/O 指標）
[root
@CESHI_Game_YALI_3
ceshi]# iostat -x -d
1
Linux
2.6
.
32
-
642.13
.
1
.el6.x86_64 (CESHI_Game_YALI_3)
05
/
09
/
2019
_x86_64_ (
4
CPU)
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await r_await w_await svctm %util
vda
0.00
0.00
0.00
72.00
0.00
72080.00
1001.11
159.52
3429.00
0.00
3429.00
13.89
100.00
dm-
0
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
dm-
1
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
dm-
2
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
dm-
3
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
|
disk屬性值說明：
- rrqm/s: 每秒進行 merge 的讀操作數目。即 rmerge/s
- wrqm/s: 每秒進行 merge 的寫操作數目。即 wmerge/s
- r/s: 每秒完成的讀 I/O 設備次數。即 rio/s
- w/s: 每秒完成的寫 I/O 設備次數。即 wio/s
- rsec/s: 每秒讀扇區數。即 rsect/s
- wsec/s: 每秒寫扇區數。即 wsect/s
- rkB/s: 每秒讀K字節數。是 rsect/s 的一半，因為每扇區大小為512字節。
- wkB/s: 每秒寫K字節數。是 wsect/s 的一半。
- avgrq-sz: 平均每次設備I/O操作的數據大小 (扇區)。
- avgqu-sz: 平均I/O隊列長度。
- await: 平均每次設備I/O操作的等待時間 (毫秒)。
- svctm: 平均每次設備I/O操作的服務時間 (毫秒)。
- %util: 一秒中有百分之多少的時間用於 I/O 操作，即被io消耗的cpu百分比
備注：如果 %util 接近 100%，說明產生的I/O請求太多，I/O系統已經滿負荷，該磁盤可能存在瓶頸。如果 svctm 比較接近 await，說明 I/O 幾乎沒有等待時間；如果 await 遠大於 svctm，說明I/O 隊列太長，io響應太慢，則需要進行必要優化。如果avgqu-sz比較大，也表示有當量io在等待。
觀察 iostat 的最后一列，你會看到，磁盤 vda 的 I/O 使用率已經高達 100%，已經 I/O 飽和。
再看前面的各個指標，每秒寫磁盤請求數是 72 ，寫大小是 72 MB，寫請求的響應時間為 3 秒，而請求隊列長度則達到了 159。
超慢的響應時間和特長的請求隊列長度，進一步驗證了 I/O 已經飽和的猜想。此時，sda 磁盤已經遇到了嚴重的性能瓶頸。
到這里，也就可以理解，為什么前面看到的 iowait 高達 100% 了，這正是磁盤 vda 的 I/O 瓶頸導致的。接下來的重點就是分析 I/O 性能瓶頸的根源了。那要怎么知道，這些 I/O 請求相關的進程呢？
5.使用 pidstat 加上 -d 參數，就可以顯示每個進程的 I/O 情況。所以，你可以在終端中運行如下命令來觀察：
[root
@CESHI_Game_YALI_3
ceshi]# pidstat -d
1
Linux
2.6
.
32
-
642.13
.
1
.el6.x86_64 (CESHI_Game_YALI_3)
05
/
09
/
2019
_x86_64_ (
4
CPU)
10
:
15
:
00
AM PID kB_rd/s kB_wr/s kB_ccwr/s Command
10
:
15
:
01
AM
522
0.00
11.88
0.00
flush-
252
:
0
10
:
15
:
01
AM
30989
0.00
44609.90
0.00
python
|
從 pidstat 的輸出，你可以發現，只有 python 進程的寫比較大，而且每秒寫的數據超過 45 MB，很明顯，正是 python 進程導致了 I/O 瓶頸。
再往下看 iodelay 項。雖然只有 python 在大量寫數據，但你應該注意到了，有兩個進程 （kworker 和 kswapd0 ）的延遲，居然比 python 進程還大很多。
綜合 pidstat 的輸出來看，還是 python 進程的嫌疑最大。接下來，我們來分析 python 進程到底在寫什么。
知道了進程的 PID 號，具體要怎么查看寫的情況呢？
想起 strace 了嗎，它正是我們分析系統調用時最常用的工具。
6.接下來，我們在終端中運行 strace 命令，並通過 -p 10805 指定 python 進程的 PID 號：
[root
@CESHI_Game_YALI_3
ceshi]# strace -p
30989
Process
30989
attached
munmap(
0x7f6aa96bb000
,
314576896
) =
0
write(
4
,
"\n"
,
1
) =
1
munmap(
0x7f6abc2bc000
,
314576896
) =
0
clock_gettime(CLOCK_MONOTONIC, {
23225970
,
456233268
}) =
0
select(
0
, NULL, NULL, NULL, {
0
,
100000
}) =
0
(Timeout)
clock_gettime(CLOCK_REALTIME, {
1557368480
,
701591410
}) =
0
getpid() =
1
mmap(NULL,
314576896
, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -
1
,
0
) =
0x7f6abc2bc000
mmap(NULL,
393220096
, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -
1
,
0
) =
0x7f6aa4bbb000
mremap(
0x7f6aa4bbb000
,
393220096
,
314576896
, MREMAP_MAYMOVE) =
0x7f6aa4bbb000
munmap(
0x7f6abc2bc000
,
314576896
) =
0
lseek(
4
,
0
, SEEK_END) =
943718535
lseek(
4
,
0
, SEEK_CUR) =
943718535
munmap(
0x7f6aa4bbb000
,
314576896
) =
0
close(
4
) =
0
stat(
"/tmp/logtest.txt.1"
, {st_mode=S_IFREG|
0644
, st_size=
943718535
, ...}) =
0
unlink(
"/tmp/logtest.txt.1"
) =
0
stat(
"/tmp/logtest.txt"
, {st_mode=S_IFREG|
0644
, st_size=
943718535
, ...}) =
0
rename(
"/tmp/logtest.txt"
,
"/tmp/logtest.txt.1"
) =
0
open(
"/tmp/logtest.txt"
, O_WRONLY|O_CREAT|O_APPEND|O_CLOEXEC,
0666
) =
4
fcntl(
4
, F_SETFD, FD_CLOEXEC) =
0
fstat(
4
, {st_mode=S_IFREG|
0644
, st_size=
0
, ...}) =
0
lseek(
4
,
0
, SEEK_END) =
0
ioctl(
4
, TIOCGWINSZ,
0x7fffda8916e0
) = -
1
ENOTTY (Inappropriate ioctl
for
device)
lseek(
4
,
0
, SEEK_CUR) =
0
ioctl(
4
, TIOCGWINSZ,
0x7fffda891600
) = -
1
ENOTTY (Inappropriate ioctl
for
device)
lseek(
4
,
0
, SEEK_CUR) =
0
mmap(NULL,
314576896
, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -
1
,
0
) =
0x7f6abc2bc000
mmap(NULL,
314576896
, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -
1
,
0
) =
0x7f6aa96bb000
write(
4
,
"2019-05-09 02:21:20,701 - __main"
...,
314572844
) =
314572844
|
從 write() 系統調用上，我們可以看到，進程向文件描述符編號為 3 的文件中，寫入了 300MB 的數據。看來，它應該是我們要找的文件。不過，write() 調用中只能看到文件的描述符編號，文件名和路徑還是未知的。
再觀察后面的 stat() 調用，你可以看到，它正在獲取 /tmp/logtest.txt.1 的狀態。 這種“點 + 數字格式”的文件，在日志回滾中非常常見。我們可以猜測，這是第一個日志回滾文件，而正在寫的日志文件路徑，則是 /tmp/logtest.txt。
當然，這只是我們的猜測，自然還需要驗證。這里，我再給你介紹一個新的工具 lsof。它專門用來查看進程打開文件列表，不過，這里的“文件”不只有普通文件，還包括了目錄、塊設備、動態庫、網絡套接字等。
接下來，我們在終端中運行下面的 lsof 命令，看看進程 18940 都打開了哪些文件：
[root
@CESHI_Game_YALI_3
ceshi]# lsof -p
30989
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
python
30989
root cwd DIR
253
,
3
4096
393217
/
python
30989
root rtd DIR
253
,
3
4096
393217
/
python
30989
root txt REG
253
,
3
28016
394264
/usr/local/bin/python3.
7
python
30989
root mem REG
253
,
3
394992
/usr/local/lib/python3.
7
/lib-dynload/_queue.cpython-37m-x86_64-linux-gnu.so (stat: No such file or directory)
python
30989
root mem REG
253
,
3
394990
/usr/local/lib/python3.
7
/lib-dynload/_pickle.cpython-37m-x86_64-linux-gnu.so (stat: No such file or directory)
python
30989
root mem REG
253
,
3
395001
/usr/local/lib/python3.
7
/lib-dynload/_struct.cpython-37m-x86_64-linux-gnu.so (stat: No such file or directory)
python
30989
root mem REG
253
,
3
395023
/usr/local/lib/python3.
7
/lib-dynload/select.cpython-37m-x86_64-linux-gnu.so (stat: No such file or directory)
python
30989
root mem REG
253
,
3
394998
/usr/local/lib/python3.
7
/lib-dynload/_socket.cpython-37m-x86_64-linux-gnu.so (stat: No such file or directory)
python
30989
root mem REG
253
,
3
394993
/usr/local/lib/python3.
7
/lib-dynload/_random.cpython-37m-x86_64-linux-gnu.so (stat: No such file or directory)
python
30989
root mem REG
253
,
3
394960
/usr/local/lib/python3.
7
/lib-dynload/_bisect.cpython-37m-x86_64-linux-gnu.so (stat: No such file or directory)
python
30989
root mem REG
253
,
3
394996
/usr/local/lib/python3.
7
/lib-dynload/_sha3.cpython-37m-x86_64-linux-gnu.so (stat: No such file or directory)
python
30989
root mem REG
253
,
3
394961
/usr/local/lib/python3.
7
/lib-dynload/_blake2.cpython-37m-x86_64-linux-gnu.so (stat: No such file or directory)
python
30989
root mem REG
253
,
3
393383
/lib/libcrypto.so.
43.0
.
1
(stat: No such file or directory)
python
30989
root mem REG
253
,
3
394981
/usr/local/lib/python3.
7
/lib-dynload/_hashlib.cpython-37m-x86_64-linux-gnu.so (stat: No such file or directory)
python
30989
root mem REG
253
,
3
395015
/usr/local/lib/python3.
7
/lib-dynload/math.cpython-37m-x86_64-linux-gnu.so (stat: No such file or directory)
python
30989
root mem REG
253
,
3
394982
/usr/local/lib/python3.
7
/lib-dynload/_heapq.cpython-37m-x86_64-linux-gnu.so (stat: No such file or directory)
python
30989
root mem REG
253
,
3
393325
/etc/localtime (path dev=
252
,
1
, inode=
1966707
)
python
30989
root mem REG
253
,
3
394372
/usr/local/lib/libpython3.7m.so.
1.0
(stat: No such file or directory)
python
30989
root mem REG
253
,
3
393380
/lib/ld-musl-x86_64.so.
1
(stat: No such file or directory)
python
30989
root 0u CHR
136
,
1
0t0
4
/
1
python
30989
root 1u CHR
136
,
1
0t0
4
/
1
python
30989
root 2u CHR
136
,
1
0t0
4
/
1
python
30989
root 3r CHR
1
,
9
0t0
297894194
/dev/urandom
python
30989
root 4w REG
252
,
1
807931904
2101841
/tmp/logtest.txt
|
這個輸出界面中，有幾列簡單介紹一下，FD 表示文件描述符號，TYPE 表示文件類型，NAME 表示文件路徑。這也是我們需要關注的重點。
再看最后一行，這說明，這個進程打開了文件 /tmp/logtest.txt，並且它的文件描述符是 4 號，而 4 后面的 w ，表示以寫的方式打開。
這跟剛才 strace 完我們猜測的結果一致，看來這就是問題的根源：進程 30989 以每次 300MB 的速度，在“瘋狂”寫日志，而日志文件的路徑是 /tmp/logtest.txt。
所以，今后，在碰到這種“狂打日志”的場景時，你可以用 iostat、strace、lsof 等工具來定位狂打日志的進程，找出相應的日志文件，再通過應用程序的接口，調整日志級別來解決問題。
7.案例結束：
docker rm -f app
|
2.磁盤IO延遲很高,該怎么辦？
今天的案例需要兩台虛擬機，其中一台是案例分析的目標機器，運行 Flask 應用，它的 IP 地址是 172.16.109.245；而另一台作為客戶端，請求單詞的熱度。
1.首先，我們在第一個虛擬機中執行下面的命令，運行本次案例要分析的目標應用：
$ docker run --name=app -p
10000
:
80
-itd feisky/word-pop
|
2.然后，在第二個終端中運行 curl 命令，訪問 http://172.16.109.245:10000/，確認案例正常啟動。你應該可以在 curl 的輸出界面里，看到一個 hello world 的輸出：
$ curl http:
//172.16.109.245:10000/
hello world
|
3.接下來，在第二個終端中，訪問案例應用的單詞熱度接口，也就是 http://172.16.109.245:1000/popularity/word
curl http:
//172.16.109.245:10000/popularity/word
|
稍等一會兒，你會發現，這個接口居然這么長時間都沒響應，究竟是怎么回事呢？我們先回到終端一來分析一下。
我們試試在第一個終端里，隨便執行一個命令，比如執行 df 命令，查看一下文件系統的使用情況。奇怪的是，這么簡單的命令，居然也要等好久才有輸出。
通過 df 我們知道，系統還有足夠多的磁盤空間。那為什么響應會變慢呢？看來還是得觀察一下，系統的資源使用情況，像是 CPU、內存和磁盤 I/O 等的具體使用情況。
這里的思路其實跟上一個案例比較類似，我們可以先用 top 來觀察 CPU 和內存的使用情況，然后再用 iostat 來觀察磁盤的 I/O 情況。
為了避免分析過程中 curl 請求突然結束，我們回到終端二，按 Ctrl+C 停止剛才的應用程序；然后，把 curl 命令放到一個循環里執行；這次我們還要加一個 time 命令，觀察每次的執行時間：
$
while
true
;
do
time curl http:
//172.16.109.245:10000/popularity/word; sleep 1; done
|
繼續回到終端一來分析性能。我們在終端一中運行 top 命令，觀察 CPU 和內存的使用情況：
觀察 top 的輸出可以發現，兩個 CPU 的 iowait 都非常高。特別是 CPU0， iowait 已經高達 50 %，而剩余內存還有 3GB，看起來也是充足的。
再往下看，進程部分有一個 python 進程的 CPU 使用率稍微有點高，達到了 48%。雖然 48% 並不能成為性能瓶頸，不過有點嫌疑——可能跟 iowait 的升高有關。
那這個 PID 號為 87829 的 python 進程，到底是不是我們的案例應用呢？
我們在第一個終端中，按下 Ctrl+C，停止 top 命令；然后執行下面的 ps 命令，查找案例應用 app.py 的 PID 號：
root
@ubuntu
:/home/xhong# ps aux|grep app.py
root
87773
0.0
0.7
95808
14804
pts/
0
Ss+
19
:
10
0
:
00
python /app.py
root
87829
17.7
0.8
97052
17620
pts/
0
Sl+
19
:
10
6
:
18
/usr/local/bin/python /app.py
root
87969
0.0
0.0
21536
1020
pts/
0
S+
19
:
46
0
:
00
grep --color=auto app.py
|
從 ps 的輸出，你可以看到，這個 CPU 使用率較高的進程，正是我們的案例應用。不過先別着急分析 CPU 問題，畢竟 iowait 已經高達 81%， I/O 問題才是我們首要解決的。
接下來，我們在終端一中，運行下面的 iostat 命令，其中:
- -d 選項是指顯示出 I/O 的性能指標；
- -x 選項是指顯示出擴展統計信息（即顯示所有 I/O 指標）。
root
@ubuntu
:/home/xhong# iostat -d -x
1
Linux
4.18
.
0
-
16
-generic (ubuntu)
03
/
12
/
2019
_x86_64_ (
2
CPU)
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
loop0
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
loop1
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
loop2
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
loop3
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
loop4
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
loop5
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
loop6
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
loop7
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
sda
0.00
410.00
0.00
301612.00
0.00
71.00
0.00
14.76
0.00
87.20
37.47
0.00
735.64
2.06
84.40
|
明白了指標含義，再來具體觀察 iostat 的輸出。你可以發現，磁盤 sda 的 I/O 使用率已經達到 84% ，接近飽和了。而且，寫請求的響應時間高達 87毫秒，每秒的寫數據為 32MB，顯然寫磁盤碰到了瓶頸。
那要怎么知道，這些 I/O 請求到底是哪些進程導致的呢？我想，你已經還記得上一節我們用到的 pidstat。
在終端一中，運行下面的 pidstat 命令，觀察進程的 I/O 情況：
root
@ubuntu
:/home/xhong# pidstat -d
1
Linux
4.18
.
0
-
16
-generic (ubuntu)
03
/
12
/
2019
_x86_64_ (
2
CPU)
08
:
03
:
10
PM UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
08
:
03
:
11
PM
1000
1997
8.00
0.00
0.00
0
Xorg
08
:
03
:
11
PM
1000
85313
32.00
0.00
0.00
17
gnome-terminal-
08
:
03
:
11
PM
0
87829
0.00
305732.00
0.00
0
python
08
:
03
:
11
PM
0
87991
0.00
0.00
0.00
25
kworker/u256:
0
-flush-
8
:
0
|
從 pidstat 的輸出，我們再次看到了 PID 號為 12280 的結果。這說明，正是案例應用引發 I/O 的性能瓶頸。
走到這一步，你估計覺得，接下來就很簡單了，上一個案例不剛剛學過嗎？無非就是，先用 strace 確認它是不是在寫文件，再用 lsof 找出文件描述符對應的文件即可。
到底是不是這樣呢？我們不妨來試試。還是在終端一中，執行下面的 strace 命令：
root
@ubuntu
:/home/xhong# strace -p
87829
strace: Process
87829
attached
select(
0
, NULL, NULL, NULL, {tv_sec=
0
, tv_usec=
997634
}) =
0
(Timeout)
futex(
0x7ffd2c24b5c4
, FUTEX_WAIT_PRIVATE,
2
, {tv_sec=
0
, tv_nsec=
4999263
}) =
0
futex(
0x7ffd2c24b5c4
, FUTEX_WAIT_PRIVATE,
2
, {tv_sec=
0
, tv_nsec=
4999719
}) =
0
|
從 strace 中，你可以看到大量的 stat 系統調用，並且大都為 python 的文件，但是，請注意，這里並沒有任何 write 系統調用。
由於 strace 的輸出比較多，我們可以用 grep ，來過濾一下 write，比如：
root
@ubuntu
:/home/xhong# strace -p
87829
2
>&
1
| grep write
|
遺憾的是，這里仍然沒有任何輸出。
難道此時已經沒有性能問題了嗎？重新執行剛才的 top 和 iostat 命令，你會不幸地發現，性能問題仍然存在。
文件寫，明明應該有相應的 write 系統調用，但用現有工具卻找不到痕跡，這時就該想想換工具的問題了。怎樣才能知道哪里在寫文件呢？
這里我給你介紹一個新工具， filetop。它是 bcc軟件包的一部分，基於 Linux 內核的 eBPF（extended Berkeley Packet Filters）機制，主要跟蹤內核中文件的讀寫情況，並輸出線程 ID（TID）、讀寫大小、讀寫類型以及文件名稱。
至於老朋友 bcc 的安裝方法，可以參考它的 Github 網站https://github.com/iovisor/bcc ,。比如在 Ubuntu 16 以上的版本中，你可以運行下面的命令來安裝它：
sudo apt-key adv --keyserver keyserver.ubuntu.com --recv-keys 4052245BD4284CDD
echo
"deb https://repo.iovisor.org/apt/$(lsb_release -cs) $(lsb_release -cs) main"
| sudo tee /etc/apt/sources.list.d/iovisor.list
sudo apt-get update
sudo apt-get install bcc-tools libbcc-examples linux-headers-$(uname -r)
|
安裝后，bcc 提供的所有工具，就全部安裝到了 /usr/share/bcc/tools 這個目錄中。接下來我們就用這個工具，觀察一下文件的讀寫情況。
首先，在終端一中運行下面的命令：
root
@ubuntu
:/home/xhong# cd /usr/share/bcc/tools
# -C 選項表示輸出新內容時不清空屏幕
root
@ubuntu
:/usr/share/bcc/tools# ./filetop -C
Tracing... Output every
1
secs. Hit Ctrl-C to end
20
:
26
:
45
loadavg:
1.48
1.32
1.18
1
/
639
88212
TID COMM READS WRITES R_Kb W_Kb T FILE
88208
python
2
0
5517
0
R
323
.txt
88208
python
2
0
4589
0
R
346
.txt
88208
python
2
0
4541
0
R
835
.txt
88208
python
2
0
4394
0
R
154
.txt
88208
python
2
0
4345
0
R
83
.txt
88208
python
2
0
4345
0
R
352
.txt
88208
python
2
0
4345
0
R
79
.txt
88208
python
2
0
4296
0
R
665
.txt
88208
python
2
0
4248
0
R
100
.txt
88208
python
2
0
4199
0
R
932
.txt
88208
python
2
0
4150
0
R
904
.txt
88208
python
2
0
4101
0
R
234
.txt
88208
python
2
0
4101
0
R
435
.txt
|
你會看到，filetop 輸出了 8 列內容，分別是線程 ID、線程命令行、讀寫次數、讀寫的大小（單位 KB）、文件類型以及讀寫的文件名稱。
這些內容里，你可能會看到很多動態鏈接庫，不過這不是我們的重點，暫且忽略即可。我們的重點，是一個 python 應用，所以要特別關注 python 相關的內容。
多觀察一會兒，你就會發現，每隔一段時間，線程號為 88208 的 python 應用就會先寫入大量的 txt 文件，再大量地讀。
線程號為 88208 的線程，屬於哪個進程呢？我們可以用 ps 命令查看。先在終端一中，按下 Ctrl+C ，停止 filetop ；然后，運行下面的 ps 命令。這個輸出的第二列內容，就是我們想知道的進程號：
root
@ubuntu
:/usr/share/bcc/tools# ps -efT | grep
88234
root
87829
88234
87773
65
20
:
31
pts/
0
00
:
00
:
15
/usr/local/bin/python /app.py
root
88241
88241
86638
0
20
:
31
pts/
0
00
:
00
:
00
grep --color=auto
88234
|
我再介紹一個好用的工具，opensnoop 。它同屬於 bcc 軟件包，可以動態跟蹤內核中的 open 系統調用。這樣，我們就可以找出這些 txt 文件的路徑。
root
@ubuntu
:/usr/share/bcc/tools# ./opensnoop
PID COMM FD ERR PATH
87829
python
6
0
/tmp/6b5efe98-
4541
-11e9-a8bd-0242ac110002/
812
.txt
87829
python
6
0
/tmp/6b5efe98-
4541
-11e9-a8bd-0242ac110002/
813
.txt
87829
python
6
0
/tmp/6b5efe98-
4541
-11e9-a8bd-0242ac110002/
814
.txt
87829
python
6
0
/tmp/6b5efe98-
4541
-11e9-a8bd-0242ac110002/
815
.txt
87829
python
6
0
/tmp/6b5efe98-
4541
-11e9-a8bd-0242ac110002/
816
.txt
87829
python
6
0
/tmp/6b5efe98-
4541
-11e9-a8bd-0242ac110002/
817
.txt
87829
python
6
0
/tmp/6b5efe98-
4541
-11e9-a8bd-0242ac110002/
818
.txt
|
綜合 filetop 和 opensnoop ，我們就可以進一步分析了。我們可以大膽猜測，案例應用在寫入 1000 個 txt 文件后，又把這些內容讀到內存中進行處理。我們來檢查一下，這個目錄中是不是真的有 1000 個文件：
root
@ubuntu
:/usr/share/bcc/tools# ls /tmp/9046db9e-fe25-11e8-b13f-0242ac110002 | wc -l
ls: cannot access
'/tmp/9046db9e-fe25-11e8-b13f-0242ac110002'
: No such file or directory
0
|
操作后卻發現，目錄居然不存在了。怎么回事呢？我們回到 opensnoop 再觀察一會兒：
root
@ubuntu
:/usr/share/bcc/tools# ./opensnoop
PID COMM FD ERR PATH
87829
python
6
0
/tmp/d607ce46-
4541
-11e9-a8bd-0242ac110002/
851
.txt
87829
python
6
0
/tmp/d607ce46-
4541
-11e9-a8bd-0242ac110002/
938
.txt
87829
python
6
0
/tmp/d607ce46-
4541
-11e9-a8bd-0242ac110002/
771
.txt
87829
python
6
0
/tmp/d607ce46-
4541
-11e9-a8bd-0242ac110002/
106
.txt
|
原來，這時的路徑已經變成了另一個目錄。這說明，這些目錄都是應用程序動態生成的，用完就刪了。
結合前面的所有分析，我們基本可以判斷，案例應用會動態生成一批文件，用來臨時存儲數據，用完就會刪除它們。但不幸的是，正是這些文件讀寫，引發了 I/O 的性能瓶頸，導致整個處理過程非常慢。
小結：
- 首先，我們用 top、iostat，分析了系統的 CPU 和磁盤使用情況。我們發現了磁盤 I/O 瓶頸，也知道了這個瓶頸是案例應用導致的。
- 接着，我們試着照搬上一節案例的方法，用 strace 來觀察進程的系統調用，不過這次很不走運，沒找到任何 write 系統調用。
- 於是，我們又用了新的工具，借助動態追蹤工具包 bcc 中的 filetop 和 opensnoop ，找出了案例應用的問題，發現這個根源是大量讀寫臨時文件。
3.當數據庫出現性能問題時，該如何分析和定位它的瓶頸呢？
預先安裝 docker、sysstat 、git、make 等工具，如 apt install docker.io sysstat make git
今天的案例需要兩台虛擬機，其中一台作為案例分析的目標機器，運行 Flask 應用，它的 IP 地址是 172.16.109.245；另一台則是作為客戶端，請求單詞的熱度。
案例總共由三個容器組成，包括一個 MySQL 數據庫應用、一個商品搜索應用以及一個數據處理的應用。其中，商品搜索應用以 HTTP 的形式提供了一個接口：
- /：返回 Index Page；
- /db/insert/products/：插入指定數量的商品信息；
- /products/：查詢指定商品的信息，並返回處理時間。
1.首先，我們在第一個虛擬機中執行下面命令，拉取本次案例所需腳本：
$ git clone https:
//github.com/feiskyer/linux-perf-examples
$ cd linux-perf-examples/mysql-slow
|
2.接着，執行下面的命令，運行本次的目標應用。正常情況下，你應該可以看到下面的輸出：
# 注意下面的隨機字符串是容器 ID，每次運行均會不同，並且你不需要關注它，因為我們只會用到名字
$ make run
docker run --name=mysql -itd -p
10000
:
80
-m 800m feisky/mysql:
5.6
WARNING: Your kernel does not support swap limit capabilities or the cgroup is not mounted. Memory limited without swap.
4156780da5be0b9026bcf27a3fa56abc15b8408e358fa327f472bcc5add4453f
docker run --name=dataservice -itd --privileged feisky/mysql-dataservice
f724d0816d7e47c0b2b1ff701e9a39239cb9b5ce70f597764c793b68131122bb
docker run --name=app --net=container:mysql -itd feisky/mysql-slow
81d3392ba25bb8436f6151662a13ff6182b6bc6f2a559fc2e9d873cd07224ab6
|
3.然后，再運行 docker ps 命令，確認三個容器都處在運行（Up）狀態：
$ docker ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
9a4e3c580963 feisky/mysql-slow
"python /app.py"
42
seconds ago Up
36
seconds app
2a47aab18082 feisky/mysql-dataservice
"python /dataservice…"
46
seconds ago Up
41
seconds dataservice
4c3ff7b24748 feisky/mysql:
5.6
"docker-entrypoint.s…"
47
seconds ago Up
46
seconds
3306
/tcp,
0.0
.
0.0
:
10000
->
80
/tcp mysql
|
MySQL 數據庫的啟動過程，需要做一些初始化工作，這通常需要花費幾分鍾時間。你可以運行 docker logs 命令，查看它的啟動過程。
當你看到下面這個輸出時，說明 MySQL 初始化完成，可以接收外部請求了：
$ docker logs -f mysql
...
... [Note] mysqld: ready
for
connections.
Version:
'5.6.42-log'
socket:
'/var/run/mysqld/mysqld.sock'
port:
3306
MySQL Community Server (GPL)
|
而商品搜索應用則是在 10000 端口監聽。你可以按 Ctrl+C ，停止 docker logs 命令；然后，執行下面的命令，確認它也已經正常運行。如果一切正常，你會看到 Index Page 的輸出：
$ curl http:
//127.0.0.1:10000/
Index P
|
4.接下來，運行 make init 命令，初始化數據庫，並插入 10000 條商品信息。這個過程比較慢，比如在我的機器中，就花了十幾分鍾時間。耐心等待一段時間后，你會看到如下的輸出：
$ make init
docker exec -i mysql mysql -uroot -P3306 < tables.sql
curl http:
//127.0.0.1:10000/db/insert/products/10000
insert
10000
lines
|
5.接着，我們切換到第二個虛擬機，訪問一下商品搜索的接口，看看能不能找到想要的商品。執行如下的 curl 命令：
$ curl http:
//10.150.89.199:10000/products/geektime
Got data: () in
15.364538192749023
sec
|
稍等一會兒，你會發現，這個接口返回的是空數據，而且處理時間超過 15 秒。這么慢的響應速度讓人無法忍受，到底出了什么問題呢？
既然今天用了 MySQL，你估計會猜到是慢查詢的問題。
不過別急，在具體分析前，為了避免在分析過程中客戶端的請求結束，我們把 curl 命令放到一個循環里執行。同時，為了避免給系統過大壓力，我們設置在每次查詢后，都先等待 5 秒，然后再開始新的請求。
6.所以，你可以在終端二中，繼續執行下面的命令：
$
while
true
;
do
curl http:
//10.150.89.199:10000/products/geektime; done
|
接下來，重新回到終端一中，分析接口響應速度慢的原因。不過，重回終端一后，你會發現系統響應也明顯變慢了，隨便執行一個命令，都得停頓一會兒才能看到輸出。
這跟上一節的現象很類似，看來，我們還是得觀察一下系統的資源使用情況，比如 CPU、內存和磁盤 I/O 等的情況。
7.我們在終端一執行 top 命令，分析系統的 CPU 使用情況：
$ top
top -
12
:
02
:
15
up
6
days,
8
:
05
,
1
user, load average:
0.66
,
0.72
,
0.59
Tasks:
137
total,
1
running,
81
sleeping,
0
stopped,
0
zombie
%Cpu0 :
0.7
us,
1.3
sy,
0.0
ni,
35.9
id,
62.1
wa,
0.0
hi,
0.0
si,
0.0
st
%Cpu1 :
0.3
us,
0.7
sy,
0.0
ni,
84.7
id,
14.3
wa,
0.0
hi,
0.0
si,
0.0
st
KiB Mem :
8169300
total,
7238472
free,
546132
used,
384696
buff/cache
KiB Swap:
0
total,
0
free,
0
used.
7316952
avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
27458
999
20
0
833852
57968
13176
S
1.7
0.7
0
:
12.40
mysqld
27617
root
20
0
24348
9216
4692
S
1.0
0.1
0
:
04.40
python
1549
root
20
0
236716
24568
9864
S
0.3
0.3
51
:
46.57
python3
22421
root
20
0
0
0
0
I
0.3
0.0
0
:
01.16
kworker/u
|
觀察 top 的輸出，我們發現，兩個 CPU 的 iowait 都比較高，特別是 CPU0，iowait 已經超過 60%。而具體到各個進程， CPU 使用率並不高，最高的也只有 1.7%。
8.既然 CPU 的嫌疑不大，那問題應該還是出在了 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
273.00
0.00
32568.00
0.00
0.00
0.00
0.00
0.00
7.90
0.00
1.16
119.30
0.00
3.56
97.20
|
iostat 的輸出你應該非常熟悉。觀察這個界面，我們發現，磁盤 sda 每秒的讀數據為 32 MB， 而 I/O 使用率高達 97% ，接近飽和，這說明，磁盤 sda 的讀取確實碰到了性能瓶頸。
9.那要怎么知道，這些 I/O 請求到底是哪些進程導致的呢？當然可以找我們的老朋友， pidstat。接下來，在終端一中，按下 Ctrl+C 停止 iostat 命令，然后運行下面的 pidstat 命令，觀察進程的 I/O 情況：
# -d 選項表示展示進程的 I/O 情況
$ pidstat -d
1
Linux
4.18
.
0
-
16
-generic (ubuntu)
03
/
14
/
2019
_x86_64_ (
2
CPU)
12
:
13
:
49
AM UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
12
:
13
:
50
AM
0
2164
0.00
3.88
0.00
0
dockerd
12
:
13
:
50
AM UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
12
:
13
:
51
AM
0
333
0.00
4.00
0.00
0
systemd-journal
12
:
13
:
51
AM
102
662
8.00
8.00
0.00
0
rsyslogd
12
:
13
:
51
AM
999
2646
421896.00
0.00
0.00
0
mysqld
12
:
13
:
51
AM
0
2800
4.00
4.00
0.00
0
python
|
從 pidstat 的輸出可以看到，PID 為 2646 的 mysqld 進程正在進行大量的讀，而且讀取速度是 42 MB/s，跟剛才 iostat 的發現一致。兩個結果一對比，我們自然就找到了磁盤 I/O 瓶頸的根源，即 mysqld 進程。
不過，這事兒還沒完。我們自然要懷疑一下，為什么 mysqld 會去讀取大量的磁盤數據呢？按照前面猜測，我們提到過，這有可能是個慢查詢問題。
要分析進程的數據讀取，當然還要靠上一節用到過的 strace+ lsof 組合。
10.接下來，還是在虛擬機一中，執行 strace 命令，並且指定 mysqld 的進程號 2646。我們知道，MySQL 是一個多線程的數據庫應用，為了不漏掉這1些線程的數據讀取情況，你要記得在執行 stace 命令時，加上 -f 參數：
$ strace -f -p
2646
[pid
28014
] read(
38
,
"934EiwT363aak7VtqF1mHGa4LL4Dhbks"
...,
131072
) =
131072
[pid
28014
] read(
38
,
"hSs7KBDepBqA6m4ce6i6iUfFTeG9Ot9z"
...,
20480
) =
20480
[pid
28014
] read(
38
,
"NRhRjCSsLLBjTfdqiBRLvN9K6FRfqqLm"
...,
131072
) =
131072
[pid
28014
] read(
38
,
"AKgsik4BilLb7y6OkwQUjjqGeCTQTaRl"
...,
24576
) =
24576
[pid
28014
] read(
38
,
"hFMHx7FzUSqfFI22fQxWCpSnDmRjamaW"
...,
131072
) =
131072
[pid
28014
] read(
38
,
"ajUzLmKqivcDJSkiw7QWf2ETLgvQIpfC"
...,
20480
) =
20480
|
觀察一會，你會發現，線程 28014 正在讀取大量數據，且讀取文件的描述符編號為 38。這兒的 38 又對應着哪個文件呢？我們可以執行下面的 11.lsof 命令，並且指定線程號 28014 ，具體查看這個可疑線程和可疑文件：
$ lsof -p
28014
|
奇怪的是，lsof 並沒有給出任何輸出。實際上，如果你查看 lsof 命令的返回值，就會發現，這個命令的執行失敗了。
12.我們知道，在 SHELL 中，特殊標量 $? 表示上一條命令退出時的返回值。查看這個特殊標量，你會發現它的返回值是 1。可是別忘了，在 Linux 中，返回值為 0 ，才表示命令執行成功。返回值為 1，顯然表明執行失敗。
$ echo $?
1
|
回過頭我們看，mysqld 的進程號是 27458，而 28014 只是它的一個線程。而且，如果你觀察 一下 mysqld 進程的線程，你會發現，mysqld 其實1還有很多正在運行的其他線程：
# -t 表示顯示線程，-a 表示顯示命令行參數
$ pstree -a -p
27458
mysqld,
27458
--log_bin=on --sync_binlog=
1
...
├─{mysqld},
27922
├─{mysqld},
27923
└─{mysqld},
28014
|
13.找到了原因，lsof 的問題就容易解決了。把線程號換成進程號，繼續執行 lsof 命令：
$ lsof -p
27458
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
...
mysqld
27458
999
38u REG
8
,
1
512440000
2601895
/var/lib/mysql/test/products.MYD
|
這次我們得到了 lsof 的輸出。從輸出中可以看到， mysqld 進程確實打開了大量文件，而根據文件描述符（FD）的編號，我們知道，描述符為 38 的是一個路徑為 /var/lib/mysql/test/products.MYD 的文件。這里注意， 38 后面的 u 表示， mysqld 以讀寫的方式訪問文件。
看到這個文件，熟悉 MySQL 的：
- MYD 文件，是 MyISAM 引擎用來存儲表數據的文件；
- 文件名就是數據表的名字；
- 而這個文件的父目錄，也就是數據庫的名字。
換句話說，這個文件告訴我們，mysqld 在讀取數據庫 test 中的 products 表。
14.實際上，你可以執行下面的命令，查看 mysqld 在管理數據庫 test 時的存儲文件。不過要注意，由於 MySQL 運行在容器中，你需要通過 docker exec 到容器中查看：
$ docker exec -it mysql ls /var/lib/mysql/test/
db.opt products.MYD products.MYI products.frm
|
從這里你可以發現，/var/lib/mysql/test/ 目錄中有四個文件，每個文件的作用分別是：
- MYD 文件用來存儲表的數據；
- MYI 文件用來存儲表的索引；
- frm 文件用來存儲表的元信息（比如表結構）；
- opt 文件則用來存儲數據庫的元信息（比如字符集、字符校驗規則等）。
當然，看到這些，你可能還有一個疑問，那就是，這些文件到底是不是 mysqld 正在使用的數據庫文件呢？有沒有可能是不再使用的舊數據呢？其實，這個很容易確認，查一下 mysqld 配置的數據路徑即可。
15.你可以在終端一中，繼續執行下面的命令：
$ docker exec -i -t mysql mysql -e
'show global variables like "%datadir%";'
+---------------+-----------------+
| Variable_name | Value |
+---------------+-----------------+
| datadir | /var/lib/mysql/ |
+---------------+-----------------+
|
這里可以看到，/var/lib/mysql/ 確實是 mysqld 正在使用的數據存儲目錄。剛才分析得出的數據庫 test 和數據表 products ，都是正在使用。
注：其實 lsof 的結果已經可以確認，它們都是 mysqld 正在訪問的文件。再查詢 datadir ，只是想換一個思路，進一步確認一下。
16.既然已經找出了數據庫和表，接下來要做的，就是弄清楚數據庫中正在執行什么樣的 SQL 了。我們繼續在終端一中，運行下面的 docker exec 命令，進入 MySQL 的命令行界面：
$ docker exec -i -t mysql mysql
...
Type
'help;'
or
'\h'
for
help. Type
'\c'
to clear the current input statement.
mysql>
|
下一步你應該可以想到，那就是在 MySQL 命令行界面中，執行 show processlist 命令，來查看當前正在執行的 SQL 語句。
17.不過，為了保證 SQL 語句不截斷，這里我們可以執行 show full processlist 命令。如果一切正常，你應該可以看到如下輸出：
mysql> show full processlist;
+----+------+-----------------+------+---------+------+--------------+-----------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+------+-----------------+------+---------+------+--------------+-----------------------------------------------------+
|
27
| root | localhost | test | Query |
0
| init | show full processlist |
|
28
| root |
127.0
.
0.1
:
42262
| test | Query |
1
| Sending data | select * from products where productName=
'geektime'
|
+----+------+-----------------+------+---------+------+--------------+-----------------------------------------------------+
2
rows in set (
0.00
sec)
|
這個輸出中，
- db 表示數據庫的名字；
- Command 表示 SQL 類型；
- Time 表示執行時間；
- State 表示狀態；
- 而 Info 則包含了完整的 SQL 語句。
多執行幾次 show full processlist 命令，你可看到 select * from products where productName=‘geektime’ 這條 SQL 語句的執行時間比較長。
再回憶一下，案例開始時，我們在終端二查詢的產品名稱 http://192.168.0.10:10000/products/geektime，其中的 geektime 也符合這條查詢語句的條件。
我們知道，MySQL 的慢查詢問題，很可能是沒有利用好索引導致的，那這條查詢語句是不是這樣呢？我們又該怎么確認，查詢語句是否利用了索引呢？
18.其實，MySQL 內置的 explain 命令，就可以幫你解決這個問題。繼續在 MySQL 終端中，運行下面的 explain 命令：
# 切換到 test 庫
mysql> use test;
# 執行 explain 命令
mysql> explain select * from products where productName=
'geektime'
;
+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
|
1
| SIMPLE | products | ALL | NULL | NULL | NULL | NULL |
10000
| Using where |
+----+-------------+----------+------+---------------+------+---------+------+-------+-------------+
1
row in set (
0.00
sec)
|
觀察這次的輸出。這個界面中，有幾個比較重要的字段需要你注意，我就以這個輸出為例，分別解釋一下：
- select_type 表示查詢類型，而這里的 SIMPLE 表示此查詢不包括 UNION 查詢或者子查詢；
- table 表示數據表的名字，這里是 products；
- type 表示查詢類型，這里的 ALL 表示全表查詢，但索引查詢應該是 index 類型才對；
- possible_keys 表示可能選用的索引，這里是 NULL；
- key 表示確切會使用的索引，這里也是 NULL；
- rows 表示查詢掃描的行數，這里是 10000。
根據這些信息，我們可以確定，這條查詢語句壓根兒沒有使用索引，所以查詢時，會掃描全表，並且掃描行數高達 10000 行。響應速度那么慢也就難怪了。
4.Redis響應嚴重延遲，該如何分析和定位？
今天的案例由 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 列表）。
今天的案例需要兩台虛擬機，其中一台用作案例分析的目標機器，運行 Flask 應用，它的 IP 地址是 172.16.109.245；而另一台作為客戶端，請求緩存查詢接口。
接下來，打開兩個終端，分別 SSH 登錄到這兩台虛擬機中。
1.首先，我們在第一個終端中，執行下面的命令，運行本次案例要分析的目標應用。正常情況下，你應該可以看到下面的輸出：
# 注意下面的隨機字符串是容器 ID，每次運行均會不同，並且你不需要關注它
$ docker run --name=redis -itd -p
10000
:
80
feisky/redis-server
ec41cb9e4dd5cb7079e1d9f72b7cee7de67278dbd3bd0956b4c0846bff211803
$ docker run --name=app --net=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://172.16.109.245:10000 ，來訪問前面提到的三個接口。
比如，我們切換到第二個虛擬機，使用 curl 工具，訪問應用首頁。如果你看到 hello redis 的輸出，說明應用正常啟動：
$ curl http:
//10.150.89.199:10000/
hello redis
|
接下來，繼續在虛擬機二中，執行下面的 curl 命令，來調用應用的 /init 接口，初始化 Redis 緩存，並且插入 5000 條緩存信息。這個過程比較慢，比如我的機器就花了十幾分鍾時間。耐心等一會兒后，你會看到下面這行輸出：
# 案例插入
5000
條數據，在實踐時可以根據磁盤的類型適當調整，比如使用 SSD 時可以調大，而 HDD 可以適當調小
#查看我的ubuntu虛擬機是HDD的，我調小到
3000
條
root
@ubuntu
:/home/xhong# curl http:
//10.150.89.199:10000/init/5000
{
"elapsed_seconds"
:
29.00375247001648
,
"keys_initialized"
:
3000
}
|
繼續執行下一個命令，訪問應用的緩存查詢接口。如果一切正常，你會看到如下輸出：
$ curl http:
//10.150.89.199:10000/get_cache
{
"count"
:
1677
,
"data"
:[
"d97662fa-06ac-11e9-92c7-0242ac110002"
,...],
"elapsed_seconds"
:
10.545469760894775
,
"type"
:
"good"
}
|
我們看到，這個接口調用居然要花 9 秒！這么長的響應時間，顯然不能滿足實際的應用需求。
到底出了什么問題呢？我們還是要用前面學過的性能工具和原理，來找到這個瓶頸。
不過別急，同樣為了避免分析過程中客戶端的請求結束，在進行性能分析前，我們先要把 curl 命令放到一個循環里來執行。你可以在虛擬機二中，繼續執行下面的命令：
$
while
true
;
do
curl http:
//10.150.89.199:10000/get_cache; done
|
接下來，再重新回到虛擬機一，查找接口響應慢的“病因”。
最近幾個案例的現象都是響應很慢，這種情況下，我們自然先會懷疑，是不是系統資源出現了瓶頸。所以，先觀察 CPU、內存和磁盤 I/O 等的使用情況肯定不會錯。
我們先在虛擬機一中執行 top 命令，分析系統的 CPU 使用情況：
觀察 top 的輸出可以發現，CPU0 的 iowait 比較高，已經達到了 82%；而各個進程的 CPU 使用率都不太高，最高的 python 和 redis-server ，也分別只有 5.3% 和 3%。再看內存，總內存 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
loop0
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
loop1
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
loop2
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
loop3
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
loop4
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
loop5
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
loop6
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
loop7
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
sda
0.00
327.00
0.00
1776.00
0.00
117.00
0.00
26.35
0.00
1.70
0.86
0.00
5.43
2.64
86.40
loop8
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
0.00
|
觀察 iostat 的輸出，我們發現，磁盤 sda 每秒的寫數據（wkB/s）為 2.5MB，I/O 使用率（%util）是 86.4%，可以看到I/O操作出現了瓶頸。
要知道 I/O 請求來自哪些進程，還是要靠我們的老朋友 pidstat。在虛擬機一中運行下面的 pidstat 命令，觀察進程的 I/O 情況：
$ pidstat -d
1
Average: UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
Average:
0
296
0.00
3.98
0.00
4
jbd2/sda1-
8
Average:
1000
85313
1.00
0.00
0.00
0
gnome-terminal-
Average:
100
90829
0.00
424.88
0.00
82
redis-server
|
從 pidstat 的輸出，我們看到，I/O 最多的進程是 PID 為 90829 的 redis-server，並且它也剛好是在寫磁盤。這說明，確實是 redis-server 在進行磁盤寫。
當然，光找到讀寫磁盤的進程還不夠，我們還要再用 strace+lsof 組合，看看 redis-server 到底在寫什么。
接下來，還是在第一個虛擬機中，執行 strace 命令，並且指定 redis-server 的進程號 90829：
# -f 表示跟蹤子進程和子線程，-T 表示顯示系統調用的時長，-tt 表示顯示跟蹤時間
$ strace -f -T -tt -p
90829
[pid
90829
]
19
:
22
:
41.294318
write(
8
,
"$6\r\nnormal\r\n"
,
12
) =
12
<
0.000188
>
[pid
90829
]
19
:
22
:
41.294582
epoll_pwait(
5
, [{EPOLLIN, {u32=
8
, u64=
8
}}],
10128
,
25
, NULL,
8
) =
1
<
0.000032
>
[pid
90829
]
19
:
22
:
41.294758
read(
8
,
"*2\r\n$3\r\nGET\r\n$41\r\nuuid:0a83bcb4-"
...,
16384
) =
61
<
0.000045
>
[pid
90829
]
19
:
22
:
41.294935
read(
3
,
0x7ffeffd94fc7
,
1
) = -
1
EAGAIN (Resource temporarily unavailable) <
0.000051
>
[pid
90829
]
19
:
22
:
41.295080
write(
8
,
"$3\r\nbad\r\n"
,
9
) =
9
<
0.000371
>
[pid
90829
]
19
:
22
:
41.295623
epoll_pwait(
5
, [{EPOLLIN, {u32=
8
, u64=
8
}}],
10128
,
24
, NULL,
8
) =
1
<
0.000107
>
[pid
90829
]
19
:
22
:
41.295859
read(
8
,
"*2\r\n$3\r\nGET\r\n$41\r\nuuid:0bf30c08-"
...,
16384
) =
61
<
0.000110
>
[pid
90829
]
19
:
22
:
41.296128
read(
3
,
0x7ffeffd94fc7
,
1
) = -
1
EAGAIN (Resource temporarily unavailable) <
0.000038
>
[pid
90829
]
19
:
22
:
41.296240
write(
8
,
"$4\r\ngood\r\n"
,
10
) =
10
<
0.000380
>
[pid
90829
]
19
:
22
:
41.296705
epoll_pwait(
5
, [{EPOLLIN, {u32=
8
, u64=
8
}}],
10128
,
23
, NULL,
8
) =
1
<
0.000034
>
[pid
90829
]
19
:
22
:
41.296833
read(
8
,
"*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n0bf"
...,
16384
) =
67
<
0.000032
>
[pid
90829
]
19
:
22
:
41.297216
read(
3
,
0x7ffeffd94fc7
,
1
) = -
1
EAGAIN (Resource temporarily unavailable) <
0.000084
>
[pid
90829
]
19
:
22
:
41.297459
write(
7
,
"*3\r\n$4\r\nSADD\r\n$4\r\ngood\r\n$36\r\n0bf"
...,
67
) =
67
<
0.000114
>
[pid
90829
]
19
:
22
:
41.297714
fdatasync(
7
) =
0
<
0.003149
>
[pid
90829
]
19
:
22
:
41.301050
write(
8
,
":1\r\n"
,
4
) =
4
<
0.000380
>
|
事實上，從系統調用來看， epoll_pwait、read、write、fdatasync 這些系統調用都比較頻繁。那么，剛才觀察到的寫磁盤，應該就是 write 或者 fdatasync 導致的了。
注：fdatasync()，linux系統調用。用來刷新數據到磁盤。
接着再來運行 lsof 命令，找出這些系統調用的操作對象：
$ lsof -p
9085
root
@ubuntu
:/home/xhong# lsof -p
90829
lsof: WARNING: can't stat() fuse.gvfsd-fuse file system /run/user/
1000
/gvfs
Output information may be incomplete.
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
redis-ser
90829
systemd-network cwd DIR
8
,
1
4096
433582
/data
redis-ser
90829
systemd-network rtd DIR
0
,
51
4096
433551
/
redis-ser
90829
systemd-network txt REG
0
,
51
8191592
433522
/usr/local/bin/redis-server
redis-ser
90829
systemd-network mem REG
8
,
1
433522
/usr/local/bin/redis-server (stat: No such file or directory)
redis-ser
90829
systemd-network mem REG
8
,
1
1076110
/etc/localtime (path inode=
672428
)
redis-ser
90829
systemd-network mem REG
8
,
1
1191269
/lib/ld-musl-x86_64.so.
1
(stat: No such file or directory)
redis-ser
90829
systemd-network 0u CHR
136
,
0
0t0
3
/dev/pts/
0
redis-ser
90829
systemd-network 1u CHR
136
,
0
0t0
3
/dev/pts/
0
redis-ser
90829
systemd-network 2u CHR
136
,
0
0t0
3
/dev/pts/
0
redis-ser
90829
systemd-network 3r FIFO
0
,
12
0t0
2327083
pipe
redis-ser
90829
systemd-network 4w FIFO
0
,
12
0t0
2327083
pipe
redis-ser
90829
systemd-network 5u a_inode
0
,
13
0
11836
[eventpoll]
redis-ser
90829
systemd-network 6u sock
0
,
9
0t0
2327085
protocol: TCP
redis-ser
90829
systemd-network 7w REG
8
,
1
9662394
433591
/data/appendonly.aof
redis-ser
90829
systemd-network 8u sock
0
,
9
0t0
2342499
protocol: TCP
|
現在你會發現，描述符編號為 3 的是一個 pipe 管道，5 號是 eventpoll，7 號是一個普通文件，而 8 號是一個 TCP socket。
結合磁盤寫的現象，我們知道，只有 7 號普通文件才會產生磁盤寫，而它操作的文件路徑是 /data/appendonly.aof，相應的系統調用包括 write 和 fdatasync。
如果你對 Redis 的持久化配置比較熟，看到這個文件路徑以及 fdatasync 的系統調用，你應該能想到，這對應着正是 Redis 持久化配置中的 appendonly 和 appendfsync 選項。很可能是因為它們的配置不合理，導致磁盤寫比較多。
注：redis持久化請看：https://blog.csdn.net/ljl890705/article/details/51039015
接下來就驗證一下這個猜測，我們可以通過 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 表示交給操作系統來處理。
回憶一下我們剛剛看到的配置，appendfsync 配置的是 always，意味着每次寫數據時，都會調用一次 fsync，從而造成比較大的磁盤 I/O 壓力。
當然，你還可以用 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 90829 的結果。
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： 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 響應延遲的潛在原因。總結一下，我們找到兩個問題。
完了在虛擬機一中結束案例：
root
@ubuntu
:/home/xhong# docker rm -f app redis
|
小結：
我們先用 top、iostat ，分析了系統的 CPU 、內存和磁盤使用情況，不過卻發現，系統資源並沒有出現瓶頸。這個時候想要進一步分析的話，該從哪個方向着手呢？
通過今天的案例你會發現，為了進一步分析，就需要你對系統和應用程序的工作原理有一定的了解。
比如，今天的案例中，雖然磁盤 I/O 並沒有出現瓶頸，但從 Redis 的原理來說，查詢緩存時不應該出現大量的磁盤 I/O 寫操作。
順着這個思路，我們繼續借助 pidstat、strace、lsof、nsenter 等一系列的工具，找出了兩個潛在問題，一個是 Redis 的不合理配置，另一個是 Python 應用對 Redis 的濫用。找到瓶頸后，相應的優化工作自然就比較輕松了。