28 | 案例篇:一个SQL查询要15秒,这是怎么回事?
生活随笔
收集整理的這篇文章主要介紹了
28 | 案例篇:一个SQL查询要15秒,这是怎么回事?
小編覺得挺不錯的,現在分享給大家,幫大家做個參考.
上一節,我們分析了一個單詞熱度應用響應過慢的案例。當用 top、iostat 分析了系統的 CPU 和磁盤 I/O 使用情況后,我們發現系統出現了磁盤的 I/O 瓶頸,而且正是案例應用導致的。接著,在使用 strace 卻沒有任何發現后,我又給你介紹了兩個新的工具 filetop 和 opensnoop,分析它們對系統調用 write() 和 open() 的追蹤結果。我們發現,案例應用正在讀寫大量的臨時文件,因此產生了性能瓶頸。找出瓶頸后,我們又用把文件數據都放在內存的方法,解決了磁盤 I/O 的性能問題。當然,你可能會說,在實際應用中,大量數據肯定是要存入數據庫的,而不會直接用文本文件的方式存儲。不過,數據庫也不是萬能的。當數據庫出現性能問題時,又該如何分析和定位它的瓶頸呢?今天我們就來一起分析一個數據庫的案例。這是一個基于 Python Flask 的商品搜索應用,商品信息存在 MySQL 中。這個應用可以通過 MySQL 接口,根據客戶端提供的商品名稱,去數據庫表中查詢商品信息。非常感謝唯品會資深運維工程師陽祥義,幫助提供了今天的案例。
案例準備
本次案例還是基于 Ubuntu 18.04,同樣適用于其他的 Linux 系統。我使用的案例環境如下所示:- 機器配置:2 CPU,8GB 內存
- 預先安裝 docker、sysstat 、git、make 等工具,如 apt install docker.io sysstat make git
- /:返回 Index Page;
- /db/insert/products/:插入指定數量的商品信息;
- /products/:查詢指定商品的信息,并返回處理時間。
案例分析
首先,我們在第一個終端中執行下面命令,拉取本次案例所需腳本:$ git clone https://github.com/feiskyer/linux-perf-examples $ cd linux-perf-examples/mysql-slow接著,執行下面的命令,運行本次的目標應用。正常情況下,你應該可以看到下面的輸出:# 注意下面的隨機字符串是容器 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 --network=container:mysql -itd feisky/mysql-slow 81d3392ba25bb8436f6151662a13ff6182b6bc6f2a559fc2e9d873cd07224ab6然后,再運行 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 mysqlMySQL 數據庫的啟動過程,需要做一些初始化工作,這通常需要花費幾分鐘時間。你可以運行 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 Page接下來,運行 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接著,我們切換到第二個終端,訪問一下商品搜索的接口,看看能不能找到想要的商品。執行如下的 curl 命令:$ curl http://192.168.0.10:10000/products/geektime Got data: () in 15.364538192749023 sec稍等一會兒,你會發現,這個接口返回的是空數據,而且處理時間超過 15 秒。這么慢的響應速度讓人無法忍受,到底出了什么問題呢?既然今天用了 MySQL,你估計會猜到是慢查詢的問題。不過別急,在具體分析前,為了避免在分析過程中客戶端的請求結束,我們把 curl 命令放到一個循環里執行。同時,為了避免給系統過大壓力,我們設置在每次查詢后,都先等待 5 秒,然后再開始新的請求。所以,你可以在終端二中,繼續執行下面的命令:$ while true; do curl http://192.168.0.10:10000/products/geektime; sleep 5; done接下來,重新回到終端一中,分析接口響應速度慢的原因。不過,重回終端一后,你會發現系統響應也明顯變慢了,隨便執行一個命令,都得停頓一會兒才能看到輸出。這跟上一節的現象很類似,看來,我們還是得觀察一下系統的資源使用情況,比如 CPU、內存和磁盤 I/O 等的情況。首先,我們在終端一執行 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 MemPID 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 python1549 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%。既然 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.20iostat 的輸出你應該非常熟悉。觀察這個界面,我們發現,磁盤 sda 每秒的讀數據為 32 MB, 而 I/O 使用率高達 97% ,接近飽和,這說明,磁盤 sda 的讀取確實碰到了性能瓶頸。那要怎么知道,這些 I/O 請求到底是哪些進程導致的呢?當然可以找我們的老朋友, pidstat。接下來,在終端一中,按下 Ctrl+C 停止 iostat 命令,然后運行下面的 pidstat 命令,觀察進程的 I/O 情況:# -d 選項表示展示進程的 I/O 情況 $ pidstat -d 1 12:04:11 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command 12:04:12 999 27458 32640.00 0.00 0.00 0 mysqld 12:04:12 0 27617 4.00 4.00 0.00 3 python 12:04:12 0 27864 0.00 4.00 0.00 0 systemd-journal從 pidstat 的輸出可以看到,PID 為 27458 的 mysqld 進程正在進行大量的讀,而且讀取速度是 32 MB/s,跟剛才 iostat 的發現一致。兩個結果一對比,我們自然就找到了磁盤 I/O 瓶頸的根源,即 mysqld 進程。不過,這事兒還沒完。我們自然要懷疑一下,為什么 mysqld 會去讀取大量的磁盤數據呢?按照前面猜測,我們提到過,這有可能是個慢查詢問題??墒?#xff0c;回想一下,慢查詢的現象大多是 CPU 使用率高(比如 100% ),但這里看到的卻是 I/O 問題??磥?#xff0c;這并不是一個單純的慢查詢問題,我們有必要分析一下 MySQL 讀取的數據。要分析進程的數據讀取,當然還要靠上一節用到過的 strace+ lsof 組合。接下來,還是在終端一中,執行 strace 命令,并且指定 mysqld 的進程號 27458。我們知道,MySQL 是一個多線程的數據庫應用,為了不漏掉這些線程的數據讀取情況,你要記得在執行 stace 命令時,加上 -f 參數:$ strace -f -p 27458 [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 又對應著哪個文件呢?我們可以執行下面的 lsof 命令,并且指定線程號 28014 ,具體查看這個可疑線程和可疑文件:$ lsof -p 28014奇怪的是,lsof 并沒有給出任何輸出。實際上,如果你查看 lsof 命令的返回值,就會發現,這個命令的執行失敗了。我們知道,在 SHELL 中,特殊標量 $? 表示上一條命令退出時的返回值。查看這個特殊標量,你會發現它的返回值是 1??墒莿e忘了,在 Linux 中,返回值為 0 ,才表示命令執行成功。返回值為 1,顯然表明執行失敗。$ echo $? 1為什么 lsof 命令執行失敗了呢?這里希望你暫停往下,自己先思考一下原因。記住我的那句話,遇到現象解釋不了,先去查查工具文檔。事實上,通過查詢 lsof 的文檔,你會發現,-p 參數需要指定進程號,而我們剛才傳入的是線程號,所以 lsof 失敗了。你看,任何一個細節都可能成為性能分析的“攔路虎”。回過頭我們看,mysqld 的進程號是 27458,而 28014 只是它的一個線程。而且,如果你觀察 一下 mysqld 進程的線程,你會發現,mysqld 其實還有很多正在運行的其他線程:# -t 表示顯示線程,-a 表示顯示命令行參數 $ pstree -t -a -p 27458 mysqld,27458 --log_bin=on --sync_binlog=1 ...├─{mysqld},27922├─{mysqld},27923└─{mysqld},28014找到了原因,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 引擎用來存儲表數據的文件;
- 文件名就是數據表的名字;
- 而這個文件的父目錄,也就是數據庫的名字。
- MYD 文件用來存儲表的數據;
- MYI 文件用來存儲表的索引;
- frm 文件用來存儲表的元信息(比如表結構);
- opt 文件則用來存儲數據庫的元信息(比如字符集、字符校驗規則等)。
- db 表示數據庫的名字;
- Command 表示 SQL 類型;
- Time 表示執行時間;
- State 表示狀態;
- 而 Info 則包含了完整的 SQL 語句。
- select_type 表示查詢類型,而這里的 SIMPLE 表示此查詢不包括 UNION 查詢或者子查詢;
- table 表示數據表的名字,這里是 products;
- type 表示查詢類型,這里的 ALL 表示全表查詢,但索引查詢應該是 index 類型才對;
- possible_keys 表示可能選用的索引,這里是 NULL;
- key 表示確切會使用的索引,這里也是 NULL;
- rows 表示查詢掃描的行數,這里是 10000。
案例思考
到這里,商品搜索應用查詢慢的問題已經完美解決了。但是,對于這個案例,我還有一點想說明一下。不知道你還記不記得,案例開始時,我們啟動的幾個容器應用。除了 MySQL 和商品搜索應用外,還有一個 DataService 應用。為什么這個案例開始時,要運行一個看起來毫不相關的應用呢?實際上,DataService 是一個嚴重影響 MySQL 性能的干擾應用。拋開上述索引優化方法不說,這個案例還有一種優化方法,也就是停止 DataService 應用。接下來,我們就刪除數據庫索引,回到原來的狀態;然后停止 DataService 應用,看看優化效果如何。首先,我們在終端二中停止 curl 命令,然后回到終端一中,執行下面的命令刪除索引:# 刪除索引 $ docker exec -i -t mysql mysql mysql> use test; mysql> DROP INDEX products_index ON products;接著,在終端二中重新運行 curl 命令。當然,這次你會發現,處理時間又變慢了:$ while true; do curl http://192.168.0.10:10000/products/geektime; sleep 5; done Got data: ()in 16.884345054626465 sec接下來,再次回到終端一中,執行下面的命令,停止 DataService 應用:# 停止 DataService 應用 $ docker rm -f dataservice最后,我們回到終端二中,觀察 curl 的結果:Got data: ()in 16.884345054626465 sec Got data: ()in 15.238174200057983 sec Got data: ()in 0.12604427337646484 sec Got data: ()in 0.1101069450378418 sec Got data: ()in 0.11235237121582031 sec果然,停止 DataService 后,處理時間從 15 秒縮短到了 0.1 秒,雖然比不上增加索引后的 3 毫秒,但相對于 15 秒來說,優化效果還是非常明顯的。那么,這種情況下,還有沒有 I/O 瓶頸了呢?我們切換到終端一中,運行下面的 vmstat 命令(注意不是 iostat,稍后解釋原因),觀察 I/O 的變化情況:$ vmstat 1 procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----r b swpd free buff cache si so bi bo in cs us sy id wa st0 1 0 6809304 1368 856744 0 0 32640 0 52 478 1 0 50 49 00 1 0 6776620 1368 889456 0 0 32640 0 33 490 0 0 50 49 00 0 0 6747540 1368 918576 0 0 29056 0 42 568 0 0 56 44 00 0 0 6747540 1368 918576 0 0 0 0 40 141 1 0 100 0 00 0 0 6747160 1368 918576 0 0 0 0 40 148 0 1 99 0 0你可以看到,磁盤讀(bi)和 iowait(wa)剛開始還是挺大的,但沒過多久,就都變成了 0 。換句話說,I/O 瓶頸消失了。這是為什么呢?原因先留個懸念,作為今天的思考題?;剡^頭來解釋一下剛剛的操作,在查看 I/O 情況時,我并沒用 iostat 命令,而是用了 vmstat。其實,相對于 iostat 來說,vmstat 可以同時提供 CPU、內存和 I/O 的使用情況。在性能分析過程中,能夠綜合多個指標,并結合系統的工作原理進行分析,對解釋性能現象通常會有意想不到的幫助。小結
今天我們分析了一個商品搜索的應用程序。我們先是通過 top、iostat 分析了系統的 CPU 和磁盤使用情況,發現了磁盤的 I/O 瓶頸。接著,我們借助 pidstat ,發現瓶頸是 mysqld 導致的。緊接著,我們又通過 strace、lsof,找出了 mysqld 正在讀的文件。同時,根據文件的名字和路徑,我們找出了 mysqld 正在操作的數據庫和數據表。綜合這些信息,我們判斷,這是一個沒有利用索引導致的慢查詢問題。于是,我們登錄到 MySQL 命令行終端,用數據庫分析工具進行驗證,發現 MySQL 查詢語句訪問的字段,果然沒有索引。所以,增加索引,就可以解決案例的性能問題了。思考最后,給你留一個思考題,也是我在案例最后部分提到過的,停止 DataService 后,商品搜索應用的處理時間,從 15 秒縮短到了 0.1 秒。這是為什么呢?我給個小小的提示。你可以先查看 dataservice.py 的源碼,你會發現,DataService 實際上是在讀寫一個僅包括 “data” 字符串的小文件。不過在讀取文件前,它會先把 /proc/sys/vm/drop_caches 改成 1。還記得這個操作有什么作用嗎?如果不記得,可以用 man 查詢 proc 文件系統的文檔。echo 1>/proc/sys/vm/drop_caches表示釋放pagecache,也就是文件緩存,而mysql讀書的數據就是文件緩存,dataservice不停的釋放文件緩存,就導致MySQL都無法利用磁盤緩存,也就慢了~正解總結
以上是生活随笔為你收集整理的28 | 案例篇:一个SQL查询要15秒,这是怎么回事?的全部內容,希望文章能夠幫你解決所遇到的問題。
- 上一篇: 27 | 案例篇:为什么我的磁盘I/O延
- 下一篇: 21丨容器化守护进程的意义:Daemon