【MySQL】《高效能MySQL》 學習筆記,第三章，伺服器效能剖析

標籤：MySQL最佳化   MySQL卡死   MySQL查詢最佳化   

第三章：伺服器效能剖析

? 本章將針對如下三個問題進行解答：

? 如何確認伺服器是否達到了效能最佳的狀態

? 找出某條語句為什麼執行不夠快

? 診斷被使用者描述成“停頓”，“堆積”，“卡死”的某些間歇性疑難故障

1.效能最佳化簡介：

? 針對效能問題，1000個DBA，有1000個回答。諸如，“QPS”,"CPU Load"，“可擴充性”之類。

原則一：我們將效能定義為完成某件任務所需要的時間度量。即：“效能就是回應時間” 。

? 通過任務和時間來度量效能而不是資源。資料庫的目的是執行SQL語句，上句中的“任務”即是查詢或者SQL語句（SELECT UPDATE DELETE等等），綜上，資料庫伺服器的效能用查詢的回應時間度量，單位則是每個查詢所花費的時間。在這裡我們先假設效能最佳化就是在一定工作負載的情況下儘可能的降低回應時間。

? CPU使用率只是一種現象，而不是很好的可度量的目標。

? 輸送量的提升可以看作效能最佳化的副產品，對查詢的最佳化可以讓伺服器每秒執行更多的查詢。因為每秒查詢執行的時間更短了。（輸送量即是效能的倒數：單位時間內查詢的數量，QPS,QPM等等）

原則二：無法測量就無法有效地最佳化。第一步應當測量時間花在什麼地方。

? 完成一項任務所需要的時間可以分成兩部分：執行時間和等待時間。

? 如果要最佳化任務的執行時間，最好的辦法是通過測量定位不同的子任務花費的時間，然後最佳化去掉一些子任務，降低子任務的執行頻率或者提升子任務的執行效率。

? 如果要最佳化任務的等待時間，則相對複雜一些，等待可能是因為其他系統間接影響所致。

1.1.通過效能剖析進行最佳化。

? 效能剖析（Profiling）分為兩個步驟：先測量任務所花費的時間，然後對結果進行統計和排序，講重要的任務排到前面。

? 效能剖析報告會列出所有工作清單。每行記錄一個任務，包括任務名，任務的執行時間，任務的消耗時間，任務的平均時間，以及該任務執行時間佔全部時間的百分比。

? 基於執行時間的分析研究的是什麼任務的執行時間最長。

? 基於等待的分析則是判斷任務在什麼階段被阻塞的時間最長。

? 事實上，當基於執行時間的分析發現一個任務需要花費時間花費太多時間的時候，應該深入去分析一下，可能會發現某些“執行時間”其實是在等待。

1.2.理解效能剖析

? 儘管效能剖析輸出了排名，總計和平均值，但還是有許多重要的資訊是缺失的。

? 值得最佳化的查詢：一些只佔總回應時間比重很小的查詢是不值得最佳化的。如果花費了1000美元去最佳化一個任務，單業務的收入沒有任何增加，那麼可以說是打水漂了。如果最佳化的成本大於收益，就應當停止最佳化。

? 異常情況:某些任務即使沒有出現在效能剖析輸出的前面也需要最佳化。比如，某些任務執行次數很少，單每次執行都非常慢，嚴重影響使用者體驗。

? 被掩藏的細節：效能剖析無法顯示所有回應時間的馮部，只相信平均值是非常危險的。正如醫院內所有病人的平均體溫一樣毫無意義。

2.對應用系統進行效能剖析

? 實際上，剖析應用程式一般比剖析資料庫伺服器更容易，且回報率更高。建議對系統進行自上而下的效能分析，這樣可以追蹤自使用者發起到伺服器響應的整個流程，雖然效能問題大多數情況下都和資料庫有關，但是應用導致的問題也不少。

# 應該儘可能地測量一切可以測量的地方，並且接受這些測量帶來的額外開銷。# Oracle 的效能最佳化大師Tom Kyte 曾被問到Oracle中的測量點開銷，他的回答是，測量點至少為效能最佳化共用10%# 大多數應用並不需要每天都運行詳盡的效能測量，所以實際上貢獻至少超過10%

3.剖析MySQL查詢3.1剖析伺服器負載

? MySQL的每一個新版本都增加了更多的可測量點。但是如果只是需要剖析並找出和代價高的查詢，慢查詢日誌應該就能滿足我們的需求。可以通過將"long_query_time"設為0來捕獲所有的查詢，並且查詢的回應時間已經可以做到微秒級 。在當前的版本中，慢日誌是開銷最低，同時精度最高的測量查詢時間的工具。如果長期開啟慢查詢日誌，主要要配合logrotate工具一同使用（

）。Percona分支的MySQL比起官方社區版本記錄了更多更有價值的資訊。如查詢計劃，鎖，I/O活動等。總的來說，慢日誌是一種輕量且全面的效能剖析工具。

? 可以使用pt-query-digest分析慢查詢日誌，如：

pt-query-digest slow.log >slow_log_analyze.log    /data/mysql/3109/slow.log:  53% 00:25 remain    /data/mysql/3109/slow.log:  98% 00:00 remaincat slow_log_analyze.log# 75.3s user time, 2s system time, 41.28M rss, 235.76M vsz# Current date: Sun Feb 25 15:43:11 2018# Hostname: MySQL-Cent7-IP001109# Files: /data/mysql/3109/slow.log# Overall: 445.27k total, 59 unique, 0.03 QPS, 0.04x concurrency _________# Time range: 2017-09-28T16:00:25 to 2018-02-25T07:27:18# Attribute          total     min     max     avg     95%  stddev  median# ============     ======= ======= ======= ======= ======= ======= =======# Exec time        461284s   100ms    150s      1s      3s      1s   740ms# Lock time          1154s       0     10s     3ms    57us    83ms    21us# Rows sent        426.70M       0   9.54M 1004.84   97.36  76.26k    0.99# Rows examine     465.04M       0   9.54M   1.07k  299.03  76.26k    0.99# Query size         4.55G       6 1022.79k  10.71k   76.28  73.23k   36.69# Profile# Rank Query ID           Response time     Calls  R/Call  V/M   Item# ==== ================== ================= ====== ======= ===== =========#    1 0x558CAEF5F387E929 238431.3966 51.7% 294383  0.8099  0.62 SELECT sbtest?#    2 0x84D1DEE77FA8D4C3  53638.8398 11.6%  33446  1.6037  1.14 SELECT sbtest?#    3 0x3821AE1F716D5205  53362.1845 11.6%  33504  1.5927  1.11 SELECT sbtest?#    4 0x737F39F04B198EF6  53244.4816 11.5%  33378  1.5952  1.14 SELECT sbtest?#    5 0x6EEB1BFDCCF4EBCD  53036.2877 11.5%  33539  1.5813  1.10 SELECT sbtest?#    6 0x67A347A2812914DF   2619.2344  0.6%    200 13.0962 67.98 SELECT tpcc?.order_line#    7 0x28FC5B5D583E2DA6   2377.9580  0.5%    215 11.0603 11.53 SHOW GLOBAL STATUS#   10 0xE730A9F41A4AB139    259.9002  0.1%    355  0.7321  0.42 SHOW INNODB STATUS#   11 0x88901A51719CB50B    131.1035  0.0%     39  3.3616 21.74 SELECT information_schema.tables#   12 0x16F46891A99F2C89    127.1865  0.0%     88  1.4453  1.15 SELECT performance_schema.events_statements_history#   14 0x153F1CE7D660AE82     79.2867  0.0%     46  1.7236  1.47 SELECT information_schema.processlist# MISC 0xMISC               3976.0946  0.9%  16077  0.2473   0.0 <47 ITEMS># Query 1: 0.17 QPS, 0.14x concurrency, ID 0x558CAEF5F387E929 at byte 4877477857# This item is included in the report because it matches --limit.# Scores: V/M = 0.62# Time range: 2018-02-03T11:26:24 to 2018-02-23T13:03:23# Attribute    pct   total     min     max     avg     95%  stddev  median:

?

? 除了慢日誌之外Percona Toolkit工具包中的pt-query-digest工具也可以進行剖析，使用--processlist參數可以不斷的分析"show processlist"的輸出。但是“show processlist”的輸出瞬息萬變。即使每秒收集一次仍會遺漏很多有用的資訊，因此並不十分推薦這種方式。另一種方式是使用--type=tcpdump選項對網路抓包資料進行分析。

3.2 剖析單條查詢使用SHOW PROFILE

? 預設禁用，但它是會話層級的參數。set profiling=1 ，然後在伺服器上直送所有的語句，都會測量其耗費的時間和其他一些查詢執行狀態變更相關的資料。

? 當一條查詢提交給伺服器時，此工具會記錄剖析資訊到一張暫存資料表，並給查詢賦一個從1開始的整數標識符。

? 如：

set profiling=1select * from t_Order;select * from t_Productshow profiles+----------+------------+-------------------------+| Query_ID | Duration   | Query                   |+----------+------------+-------------------------+| 1        | 9.75e-05   | SHOW WARNINGS           || 2        | 0.00052075 | select * from t_order   || 3        | 0.000511   | select * from t_product || 4        | 5.3e-05    | SHOW WARNINGS           |+----------+------------+-------------------------+show profile for query 3+----------------------+----------+| Status               | Duration |+----------------------+----------+| starting             | 0.000065 || checking permissions | 0.000009 || Opening tables       | 0.000142 || init                 | 0.000022 || System lock          | 0.000010 || optimizing           | 0.000008 || statistics           | 0.000013 || preparing            | 0.000012 || executing            | 0.000007 || Sending data         | 0.000154 || end                  | 0.000010 || query end            | 0.000011 || closing tables       | 0.000010 || freeing items        | 0.000016 || cleaning up          | 0.000012 |+----------------------+----------+

? 剖析報告給出了查詢執行的每個步驟及其花費的時間，看結果很難快速地確定哪個步驟花費的時間最多。輸出是按照執行順序進行排序，而不是按照花費的時間排序的。下面給出使用INFORMATION_SHCEMA來查詢剖析報告的辦法：

set @query_id=1SELECT STATE,SUM(DURATION) AS  Total_R,    ROUND(    100*SUM(DURATION)/(SELECT SUM(DURATION) FROM INFORMATION_SCHEMA.PROFILING WHERE QUERY_ID = @query_id),2         ) AS Pct_R,COUNT(*) AS Calls,SUM(DURATION)/COUNT(*) AS "R/Call"FROM INFORMATION_SCHEMA.PROFILINGWHERE [email protected]_idGROUP BY STATEORDER BY Total_R DESC# 輸出如下：+----------------------+----------+-------+-------+--------------+| STATE                | Total_R  | Pct_R | Calls | R/Call       |+----------------------+----------+-------+-------+--------------+| starting             | 0.000072 | 20.45 | 1     | 0.0000720000 || Sending data         | 0.000047 | 13.35 | 1     | 0.0000470000 || init                 | 0.000030 | 8.52  | 1     | 0.0000300000 || Opening tables       | 0.000026 | 7.39  | 1     | 0.0000260000 || checking permissions | 0.000025 | 7.10  | 1     | 0.0000250000 || cleaning up          | 0.000023 | 6.53  | 1     | 0.0000230000 || System lock          | 0.000019 | 5.40  | 1     | 0.0000190000 || statistics           | 0.000018 | 5.11  | 1     | 0.0000180000 || preparing            | 0.000016 | 4.55  | 1     | 0.0000160000 || optimizing           | 0.000015 | 4.26  | 1     | 0.0000150000 || freeing items        | 0.000014 | 3.98  | 1     | 0.0000140000 || query end            | 0.000013 | 3.69  | 1     | 0.0000130000 || closing tables       | 0.000012 | 3.41  | 1     | 0.0000120000 || executing            | 0.000011 | 3.13  | 1     | 0.0000110000 || end                  | 0.000011 | 3.13  | 1     | 0.0000110000 |+----------------------+----------+-------+-------+--------------+#通過這個結果可以很容易看到查詢時間長主要是因為花了很大時間在sending data上#這個狀態 代表的原因非常多，可能是各種不同的伺服器活動，包括在關聯時搜尋匹配的行記錄等，這部分很難說能最佳化節省多少消耗的時間。#若Sorting result花費的時間比較多，則可以考慮增大sort buffer size

使用show status

? MySQL的show status 命令返回了一些計數器，既有伺服器層級的全域技術去，也有基於某個串連的會話層級的計數器。MySQL官方手冊對與所有的變數是全域還是會話層級的做了詳細的說明。

? show status的大部分結果都是一個計數器，可以顯示某些活動如讀索引的頻繁程度，但無法給出消耗了多少時間。show status的結果中只有一條Innodb_row_lock_time指的是操作時間，而且這個是全域性的，還是無法測量會話層級的工作。最有用的計數器包括控制代碼計數器，臨時檔案和表計數器等。將會話層級的計數器重設為0，然後查詢前面提到的視圖，再檢查計數器的結果：

flush status;select * from sakila.nicer_but_slower_film_list;#...............show status where variable_name like "Handler%" or Variable_name like "Created%";+----------------------------+-------+| Variable_name              | Value |+----------------------------+-------+| Created_tmp_disk_tables    | 2     || Created_tmp_files          | 2     || Created_tmp_tables         | 3     || Handler_commit             | 1     || Handler_delete             | 0     || Handler_discover           | 0     || Handler_external_lock      | 10    || Handler_mrr_init           | 0     || Handler_prepare            | 0     || Handler_read_first         | 3     || Handler_read_key           | 12942 || Handler_read_last          | 0     || Handler_read_next          | 6462  || Handler_read_prev          | 0     || Handler_read_rnd           | 5462  || Handler_read_rnd_next      | 6478  || Handler_rollback           | 0     || Handler_savepoint          | 0     || Handler_savepoint_rollback | 0     || Handler_update             | 0     || Handler_write              | 0     |+----------------------------+-------+

從結果可以看到該查詢使用了三個暫存資料表，其中兩個是磁碟暫存資料表，並且有很多的沒有用到索引的讀操作（Handler_read_rnd_next）。假設我們不知道這個視圖的具體定義，僅從結果來推測，這個查詢可能做了多表關聯查詢，且沒有合適的索引，可能是其中一個子查詢建立了暫存資料表，然後和其他表做聯集查詢，而用於儲存子查詢結果的暫存資料表沒有索引。

? 但是，請注意，使用show status本身也會建立一個暫存資料表，而且也會通過控制代碼操作訪問此暫存資料表，也會影響到show status結果中對應的數字，而且不同的版本可能行為也不盡相同，比較前面通過show profiles獲得的查詢的的執行計畫結果來看，至少暫存資料表的計數器多加了2。
? 通過explain看到的查詢執行計畫也可以獲得和show status大部分相同的資訊，但是通過explain是估計得到的結果，而通過show status則是實際測量的結果。比如，explain無法告訴你暫存資料表是否是磁碟表。

【MySQL】《高效能MySQL》 學習筆記,第三章，伺服器效能剖析