21丨MySQL：資料庫級監控及常用計數器解析（下）
阿新 • • 發佈：2020-08-17
上一篇文章中，我們講了有關資料庫的全域性分析，那麼在今天的文章中，我們繼續看看在資料庫中，如何做定向分析。
還記得我在上篇文章中提到的工具嗎？mysqlreport、pt-query-digest和mysql_exportor+Prometheus+Grafana。我們在上一篇中已經講完了mysqlreport，今天我們來看看剩下的這幾個。
定向抓取SQL：pt-query-digest
pt-query-digest是個挺好的工具，它可以分析slow log、general log、binary log，還能分析tcpdump抓取的MySQL協議資料，可見這個工具有多強大。pt-query-digest
pt-query-digest分析slow log時產生的報告邏輯非常清晰，並且資料也比較完整。執行命令後就會生成一個報告。
我來稍微解釋一下這個報告。我們先看這個報告的第一個部分：
# 88.3s user time, 2.5s system time, 18.73M rss, 2.35G vsz # Current date: Thu Jun 22 11:30:02 2017 # Hostname: localhost # Files: /Users/Zee/Downloads/log/10.21.0.30/4001/TENCENT64-slow.log.last # Overall: 210.18k total, 43 unique, 0.26 QPS, 0.14x concurrency _________ # Time range: 2017-06-12 21:20:51 to 2017-06-22 09:26:38 # Attribute total min max avg 95% stddev median # ============ ======= ======= ======= ======= ======= ======= ======= # Exec time 118079s 100ms 9s 562ms 2s 612ms 293ms # Lock time 15s 0 7ms 71us 119us 38us 69us # Rows sent 1.91M 0 48.42k 9.53 23.65 140.48 2.90 # Rows examine 13.99G 0 3.76M 69.79k 101.89k 33.28k 68.96k # Rows affecte 3.36M 0 1.98M 16.76 0.99 4.90k 0 # Query size 102.82M 6 10.96k 512.99 719.66 265.43 719.66
從上表中可以看得出來，在這個慢日誌中，總執行時間達到了118079s，平均執行時間為562ms，最長執行時間為9s，標準方差為612ms。
可見在此示例中，SQL執行還是有點慢的。
這時也許會有人問，SQL執行多長時間才是慢呢？之前在一個金融機構，我跟一個做核心系統的團隊討論他們的SQL執行時間指標。他們判斷之後說，希望SQL平均執行時間指標定在500ms。我說，你們要500ms，那前面還有一連串的節點才能到達最終的使用者，如果每個環節都這樣要求自己，那最終的使用者不就明顯感覺到很慢了嗎？
經過一輪輪的討論，最後定在了100ms以內。
其實從我的經驗上來看，對於大部分實時的業務，一個SQL執行的平均時間指標定在100ms都多了。但是對效能來說就是這樣，在所有的環節中都沒有固定的標準，只有經驗資料和不斷演化的系統性能能力。
我們再接著分析上面的資料。再來看pt-query-digest給出的負載報表：
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ================ ====== ====== ===== ===========
# 1 0x6A516B681113449F 73081.7989 61.9% 76338 0.9573 0.71 UPDATE mb_trans
# 2 0x90194A5C40980DA7 38014.5008 32.2% 105778 0.3594 0.20 SELECT mb_trans mb_trans_finan
# 3 0x9B56065EE2D0A5C8 3893.9757 3.3% 9709 0.4011 0.11 UPDATE mb_finan
# MISC 0xMISC 3088.5453 2.6% 18353 0.1683 0.0 <40 ITEMS>
從這個表中可以看到，有兩個SQL的執行時間佔了總執行時間的94%，顯然這兩個SQL是要接下來要分析的重點。
我們再接著看這個工具給出的第一個SQL的效能報表：
# Query 1: 0.30 QPS, 0.29x concurrency, ID 0x6A516B681113449F at byte 127303589
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.71
# Time range: 2017-06-16 21:12:05 to 2017-06-19 18:50:59
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 36 76338
# Exec time 61 73082s 100ms 5s 957ms 2s 823ms 672ms
# Lock time 19 3s 20us 7ms 38us 66us 29us 33us
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 36 5.06G 3.82k 108.02k 69.57k 101.89k 22.70k 68.96k
# Rows affecte 2 74.55k 1 1 1 1 0 1
# Query size 12 12.36M 161 263 169.75 192.76 11.55 158.58
# String:
# Databases db_bank
# Hosts 10.21.16.50 (38297/50%)... 1 more
# Users user1
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms ################################################################
# 1s #########################################
# 10s+
# Tables
# SHOW TABLE STATUS FROM `db_bank` LIKE 'mb_trans'\G
# SHOW CREATE TABLE `db_bank`.`mb_trans`\G
UPDATE mb_trans
SET
resCode='PCX00000',resultMes='交易成功',payTranStatus='P03',payRouteCode='CMA'
WHERE
seqNo='20170619PM010394356875'\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select
resCode='PCX00000',resultMes='交易成功',payTranStatus='P03',payRouteCode='CMA' from mb_trans where
seqNo='20170619PM010394356875'\G
從查詢時間分佈圖上來看，這個語句的執行時間在100ms~1s之間居多，95%的執行時間在2s以下。那麼這個SQL就是我們接下來要調優的重點了。
第二個SQL我就不贅述了，因為邏輯是完全一樣的。
通過對慢日誌的分析，我們可以很快知道哪個SQL是慢的了。當然你用mysqldumpslow分析，也會得到一樣的結果。
SQL剖析：profiling
在分析資料庫的效能時，顯然對SQL的分析是繞不過去的一個環節。但是我之前也說過了，上來就對SQL進行全面剖析也是不合邏輯的，因為SQL那麼多，如果對每個SQL都進行詳細的執行步驟解析，顯然會拖慢整個系統，而且，對一些執行快的SQL進行分析也沒有什麼必要，徒增資源消耗。
通過上面的分析過程，我們已經定位到了具體是哪個SQL執行得慢，那麼下面就是要知道SQL的執行細節。無論是在Oracle還是在MySQL中，我們都要去看執行計劃。
比如說下面這樣的：
上圖中select_type是子句型別的意思，有簡單有複雜，但是它不能說明什麼成本的問題。在這裡，最重要的內容是type，因為type可以告訴你訪問這個表的時候，是通過什麼樣的方式訪問的。上圖中的ALL是全表掃描的意思。type還有如下幾個值：
執行計劃中的possible_keys會列出可能使用到的索引值。key這一列會列出執行時使用到的索引值。
以上資訊就是MySQL的執行計劃中比較重要的部分了。這些資訊可以幫助我們做SQL的分析，為優化提供證據。
除了執行計劃外，MySQL還提供了profiling，這個有什麼用呢？它可以把SQL執行的每一個步驟詳細列出來，從一個SQL進入到資料庫中，到執行完這整個生命週期。
MySQL的profiling在session級生效，所以當你用了慢日誌，知道哪個SQL有問題之後，再用這個功能是最見成效的。如果想一開始就把所有session的SQL profiling功能開啟，那成本就太高了。
下面我來詳細解釋一下profiling的用法和功能。
profiling操作步驟
profiling的操作步驟比較簡單，如下所示：
步驟一 ：set profiling=1; //這一步是為了開啟profiling功能
步驟二 ：執行語句 //執行你從慢日誌中看到的語句
步驟三 ：show profiles; //這一步是為了查詢步驟二中執行的語句的ID
步驟四 ：show profile all for query id; //這一步是為了顯示出profiling的結果
我們實際執行一下上面的步驟：
// 步驟一：開啟profiling功能
mysql> set profiling=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)
// 這一步只是為了確認一下profiles列表有沒有值，可以不用執行。
mysql> show profiles;
Empty set, 1 warning (0.00 sec)
// 步驟二：執行語句
mysql> select * from t_user where user_name='Zee0355916';
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
| id | user_number | user_name | org_id | email | mobile | create_time |
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
| 00000d2d-32a8-11ea-91f8-00163e124cff | 00009496 | Zee0355916 | NULL | [email protected] | 17600009498 | 2020-01-09 14:19:32 |
| 77bdb1ef-32a6-11ea-91f8-00163e124cff | 00009496 | Zee0355916 | NULL | [email protected] | 17600009498 | 2020-01-09 14:08:34 |
| d4338339-32a2-11ea-91f8-00163e124cff | 00009496 | Zee0355916 | NULL | [email protected] | 17600009498 | 2020-01-09 13:42:31 |
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
3 rows in set (14.33 sec)
// 步驟三：檢視profiles列表中，有了我們剛才執行的語句
mysql> show profiles;
+----------+-------------+---------------------------------------------------+
| Query_ID | Duration | Query |
+----------+-------------+---------------------------------------------------+
| 1 | 14.34078475 | select * from t_user where user_name='Zee0355916' |
+----------+-------------+---------------------------------------------------+
1 row in set, 1 warning (0.00 sec)
// 步驟四：看這個語句的profile資訊
mysql> show profile all for query 1;
+--------------------------------+-----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file | Source_line |
+--------------------------------+-----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
| starting | 0.000024 | 0.000012 | 0.000005 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL |
| Waiting for query cache lock | 0.000004 | 0.000003 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
| init | 0.000003 | 0.000002 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
| checking query cache for query | 0.000052 | 0.000036 | 0.000015 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | send_result_to_client | sql_cache.cc | 1601 |
| checking permissions | 0.000007 | 0.000005 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_parse.cc | 5316 |
| Opening tables | 0.000032 | 0.000023 | 0.000009 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | open_tables | sql_base.cc | 5095 |
| init | 0.000042 | 0.000029 | 0.000013 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_prepare_select | sql_select.cc | 1051 |
| System lock | 0.000016 | 0.000011 | 0.000004 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_lock_tables | lock.cc | 304 |
| Waiting for query cache lock | 0.000003 | 0.000002 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
| System lock | 0.000020 | 0.000014 | 0.000006 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
| optimizing | 0.000012 | 0.000009 | 0.000004 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 139 |
| statistics | 0.000019 | 0.000013 | 0.000005 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 365 |
| preparing | 0.000015 | 0.000010 | 0.000005 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 488 |
| executing | 0.000004 | 0.000003 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec | sql_executor.cc | 110 |
| Sending data | 14.324781 | 4.676869 | 0.762349 | 1316 | 132 | 2499624 | 288 | 0 | 0 | 8 | 30862 | 0 | exec | sql_executor.cc | 190 |
| end | 0.000015 | 0.000007 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_select | sql_select.cc | 1106 |
| query end | 0.000006 | 0.000005 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 5015 |
| closing tables | 0.000016 | 0.000013 | 0.000003 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 5063 |
| freeing items | 0.000013 | 0.000010 | 0.000003 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2 | 0 | mysql_parse | sql_parse.cc | 6490 |
| Waiting for query cache lock | 0.000003 | 0.000002 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
| freeing items | 0.000014 | 0.000012 | 0.000003 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
| Waiting for query cache lock | 0.000003 | 0.000002 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
| freeing items | 0.000003 | 0.000002 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
| storing result in query cache | 0.000004 | 0.000002 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | end_of_result | sql_cache.cc | 1034 |
| logging slow query | 0.015645 | 0.000084 | 0.000020 | 2 | 0 | 16 | 8 | 0 | 0 | 0 | 2 | 0 | log_slow_do | sql_parse.cc | 1935 |
| cleaning up | 0.000034 | 0.000024 | 0.000006 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 1837 |
+--------------------------------+-----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
26 rows in set, 1 warning (0.02 sec)
非常長，從這樣的資料中，我們就看到了一個語句在資料庫中從開始到結束的整個生命週期。
對生命週期中的每個步驟進行統計之後，我們就可以看到每個步驟所消耗的時間。不僅如此，還能看到如下這些資訊：
- BLOCK IO
- Context Switches
- CPU
- IPC
- MEMORY
- Page Fault
- SOURCE
- SWAPS
有了這些資訊，我們基本上就可以判斷語句哪裡有問題了。
從上面這個示例語句中，你可以看到Sending data這一步消耗了14秒的時間，並且從後面的資料中，也可以看到主動上下文切換有1316次，被動的有132次，塊操作的量也非常大。
碰到這樣的情況，我們就得先知道這個Sending data到底是什麼東西。下面我們結合之前說的到的執行計劃，一起看一下：
mysql> explain select * from t_user where user_name='Zee0355916';
+----+-------------+--------+------+---------------+------+---------+------+---------+-------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+-------------+--------+------+---------------+------+---------+------+---------+-------------+
| 1 | SIMPLE | t_user | ALL | NULL | NULL | NULL | NULL | 3868195 | Using where |
+----+-------------+--------+------+---------------+------+---------+------+---------+-------------+
1 row in set (0.00 sec)
這就是個典型的全表掃描，所以下一步就是檢查有沒有建立索引。
mysql> show indexes from t_user;
+--------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
| Table | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment |
+--------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
| t_user | 0 | PRIMARY | 1 | id | A | 3868195 | NULL | NULL | | BTREE | | |
+--------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
1 row in set (0.00 sec)
mysql>
還是有一個主鍵索引的，但由於我們沒用主鍵來查，所以用不到。
有些效能測試工程師面對這種情況可能會有這種想法：第一次沒有查索引，但是把所有資料都調到快取裡了呀，所以第二次就快了嘛，於是有些人可能想盡快“完成”工作，就用重複的資料。
這裡我再執行一遍，你可以看看是什麼結果：
+----------+-------------+-----------------------------------------------------------+
| Query_ID | Duration | Query |
+----------+-------------+-----------------------------------------------------------+
| 1 | 14.34078475 | select * from t_user where user_name='Zee0355916' |
| 2 | 0.00006675 | show profile all for 1 |
| 3 | 0.00031700 | explain select * from t_user where user_name='Zee0355916' |
| 4 | 0.00040025 | show indexes from t_user |
+----------+-------------+-----------------------------------------------------------+
6 rows in set, 1 warning (0.00 sec)
mysql> select * from t_user where user_name='Zee0355916';
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
| id | user_number | user_name | org_id | email | mobile | create_time |
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
| 00000d2d-32a8-11ea-91f8-00163e124cff | 00009496 | Zee0355916 | NULL | [email protected] | 17600009498 | 2020-01-09 14:19:32 |
| 77bdb1ef-32a6-11ea-91f8-00163e124cff | 00009496 | Zee0355916 | NULL | [email protected] | 17600009498 | 2020-01-09 14:08:34 |
| d4338339-32a2-11ea-91f8-00163e124cff | 00009496 | Zee0355916 | NULL | [email protected] | 17600009498 | 2020-01-09 13:42:31 |
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
3 rows in set (0.00 sec)
mysql> show profiles;
+----------+-------------+-----------------------------------------------------------+
| Query_ID | Duration | Query |
+----------+-------------+-----------------------------------------------------------+
| 1 | 14.34078475 | select * from t_user where user_name='Zee0355916' |
| 2 | 0.00006675 | show profile all for 1 |
| 3 | 0.00031700 | explain select * from t_user where user_name='Zee0355916' |
| 4 | 0.00040025 | show indexes from t_user |
| 5 | 0.00027325 | select * from t_user where user_name='Zee0355916' |
+----------+-------------+-----------------------------------------------------------+
7 rows in set, 1 warning (0.00 sec)
mysql> show profile all for query 5;
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+--------------+-------------+
| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file | Source_line |
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+--------------+-------------+
| starting | 0.000029 | 0.000018 | 0.000004 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL |
| Waiting for query cache lock | 0.000006 | 0.000003 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
| init | 0.000003 | 0.000003 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
| checking query cache for query | 0.000008 | 0.000006 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | send_result_to_client | sql_cache.cc | 1601 |
| checking privileges on cached | 0.000003 | 0.000002 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | send_result_to_client | sql_cache.cc | 1692 |
| checking permissions | 0.000010 | 0.000192 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_parse.cc | 5316 |
| sending cached result to clien | 0.000210 | 0.000028 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | send_result_to_client | sql_cache.cc | 1803 |
| cleaning up | 0.000006 | 0.000006 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 1837 |
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+--------------+-------------+
8 rows in set, 1 warning (0.00 sec)
mys
看到沒有，在用重複資料的時候確實會讓響應時間快很多，因為資料直接從cache中發給client了。
但是，這種作法請你堅決制止，因為它不符合真實生產的樣子。當你再換一個數據的時候，就會歇菜，還要再經過14秒的時間做全表掃描。
所以正確的做法是建立合適的索引，讓語句在執行任何一條資料時都能快起來，那麼，我們現在就建立一個索引，再看執行結果。
// 建立索引
mysql> ALTER TABLE t_user ADD INDEX username_idx (user_name);
Query OK, 0 rows affected (44.69 sec)
Records: 0 Duplicates: 0 Warnings: 0
// 分析表
mysql> analyze table t_user;
+-----------+---------+----------+----------+
| Table | Op | Msg_type | Msg_text |
+-----------+---------+----------+----------+
| pa.t_user | analyze | status | OK |
+-----------+---------+----------+----------+
1 row in set (0.08 sec)
// 執行語句
mysql> select * from t_user where user_name='Zee0046948';
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
| id | user_number | user_name | org_id | email | mobile | create_time |
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
| 000061a2-31c2-11ea-8d89-00163e124cff | 00009496 | Zee0046948 | NULL | [email protected] | 17600009498 | 2020-01-08 10:53:08 |
| 047d7ae1-32a2-11ea-91f8-00163e124cff | 00009496 | Zee0046948 | NULL | [email protected] | 17600009498 | 2020-01-09 13:36:42 |
| 1abfa543-318f-11ea-8d89-00163e124cff | 00009496 | Zee0046948 | NULL | [email protected] | 17600009498 | 2020-01-08 04:48:48 |
| 671c4014-3222-11ea-91f8-00163e124cff | 00009496 | Zee0046948 | NULL | [email protected] | 17600009498 | 2020-01-08 22:23:12 |
| 9de16dd3-32a5-11ea-91f8-00163e124cff | 00009496 | Zee0046948 | NULL | [email protected] | 17600009498 | 2020-01-09 14:02:28 |
| dd4ab182-32a4-11ea-91f8-00163e124cff | 00009496 | Zee0046948 | NULL | [email protected] | 17600009498 | 2020-01-09 13:57:05 |
| f507067e-32a6-11ea-91f8-00163e124cff | 00009496 | Zee0046948 | NULL | [email protected] | 17600009498 | 2020-01-09 14:12:04 |
| f7b82744-3185-11ea-8d89-00163e124cff | 00009496 | Zee0046948 | NULL | [email protected] | 17600009498 | 2020-01-08 03:43:24 |
+--------------------------------------+-------------+------------+--------+----------------------+-------------+---------------------+
8 rows in set (0.02 sec)
// 檢視Query_ID
mysql> show profiles;
+----------+-------------+-----------------------------------------------------------+
| Query_ID | Duration | Query |
+----------+-------------+-----------------------------------------------------------+
| 1 | 14.34078475 | select * from t_user where user_name='Zee0355916' |
| 2 | 0.00006675 | show profile all for 1 |
| 3 | 0.00031700 | explain select * from t_user where user_name='Zee0355916' |
| 4 | 0.00005875 | show indexes for table t_user |
| 5 | 0.00005850 | show indexes for t_user |
| 6 | 0.00040025 | show indexes from t_user |
| 7 | 0.00027325 | select * from t_user where user_name='Zee0355916' |
| 8 | 0.00032100 | explain select * from t_user where user_name='Zee0355916' |
| 9 | 12.22490550 | select * from t_user where user_name='Zee0046945' |
| 10 | 0.00112450 | select * from t_user limit 20 |
| 11 | 44.68370500 | ALTER TABLE t_user ADD INDEX username_idx (user_name) |
| 12 | 0.07385150 | analyze table t_user |
| 13 | 0.01516450 | select * from t_user where user_name='Zee0046948' |
+----------+-------------+-----------------------------------------------------------+
13 rows in set, 1 warning (0.00 sec)
// 檢視profile資訊
mysql> show profile all for query 13;
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file | Source_line |
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
| starting | 0.000030 | 0.000017 | 0.000004 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL |
| Waiting for query cache lock | 0.000005 | 0.000004 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
| init | 0.000003 | 0.000002 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
| checking query cache for query | 0.000060 | 0.000050 | 0.000011 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | send_result_to_client | sql_cache.cc | 1601 |
| checking permissions | 0.000009 | 0.000007 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_parse.cc | 5316 |
| Opening tables | 0.000671 | 0.000412 | 0.000000 | 1 | 0 | 8 | 0 | 0 | 0 | 0 | 1 | 0 | open_tables | sql_base.cc | 5095 |
| init | 0.006018 | 0.000082 | 0.000899 | 1 | 0 | 5408 | 0 | 0 | 0 | 1 | 0 | 0 | mysql_prepare_select | sql_select.cc | 1051 |
| System lock | 0.000017 | 0.000011 | 0.000003 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_lock_tables | lock.cc | 304 |
| Waiting for query cache lock | 0.000003 | 0.000003 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
| System lock | 0.000019 | 0.000015 | 0.000004 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
| optimizing | 0.000012 | 0.000010 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc | 139 |
| statistics | 0.001432 | 0.000167 | 0.000037 | 1 | 0 | 32 | 0 | 0 | 0 | 0 | 4 | 0 | optimize | sql_optimizer.cc | 365 |
| preparing | 0.000026 | 0.000043 | 0.000009 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | optimize | sql_optimizer.cc | 488 |
| executing | 0.000034 | 0.000005 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | exec | sql_executor.cc | 110 |
| Sending data | 0.006727 | 0.000439 | 0.001111 | 13 | 0 | 1536 | 0 | 0 | 0 | 0 | 1 | 0 | exec | sql_executor.cc | 190 |
| end | 0.000014 | 0.000007 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_select | sql_select.cc | 1106 |
| query end | 0.000009 | 0.000008 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 5015 |
| closing tables | 0.000015 | 0.000012 | 0.000003 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc | 5063 |
| freeing items | 0.000010 | 0.000008 | 0.000002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | mysql_parse | sql_parse.cc | 6490 |
| Waiting for query cache lock | 0.000003 | 0.000002 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
| freeing items | 0.000027 | 0.000022 | 0.000005 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
| Waiting for query cache lock | 0.000003 | 0.000002 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
| freeing items | 0.000003 | 0.000002 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | try_lock | sql_cache.cc | 468 |
| storing result in query cache | 0.000004 | 0.000004 | 0.000001 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | end_of_result | sql_cache.cc | 1034 |
| cleaning up | 0.000015 | 0.000012 | 0.000003 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc | 1837 |
+--------------------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------+-------------+
25 rows in set, 1 warning (0.01 sec)
mysql>
從上面最後的profile資訊你可以看出來，步驟一點沒少，但是速度快了很多，這才是正確的優化思路。
在上一篇文章中，我描述了在一個數據庫中，如何從全域性監控的角度檢視資料，今天講的是如何找到具體慢的SQL，以及如何定位這個SQL的問題。
當然不是所有的情況下，都是SQL的問題，也有可能是配置的問題，也有可能是硬體的問題。不管什麼樣的問題，其分析思路都是這樣的，也就是我總是在強調的：全域性監控-定向監控。
當然，在這裡我也應該給出MySQL分析決策樹的思路。從mysqlreport的劃分上，給出幾個具體的分析決策樹的樹枝。
這是常見的問題，如果你有興趣，可以自己完善這棵完整的樹，因為你可能會有不一樣的劃分計數器的工具或思路，所以這個樹是可以靈活變化的。
你一定要記得，別人給你的東西，永遠變不成自己的東西，它們只能引導你。如果你自己動手去做一遍，哪怕只畫出一個分枝來，都會是很大的進步。
如果你想用其他的全域性監控工具，也可以考慮如下的組合，也就是mysql_exportor+Prometheus+Grafana。
mysql_exportor+Prometheus+Grafana
我在前面也屢次提到過這類組合，不同的exportors結合Prometheus+Grafana，可以實現實時監控及資料的儲存。
在這裡我們看一下mysql_exportor可以給我們提供什麼樣的監控資料。這裡截幾個圖，給你大概看一下這個套裝工具能看什麼內容，有興趣的話，你也可以自己搭建一下。
總結
有關資料庫的知識實在是太多了，在這兩篇文章中，我重點想告訴你的，就是分析資料庫應該具有的思路。至於其他的知識點，我想應該是你開啟文章之前就應該儲備的東西。
我們再來總結一下，在資料庫的分析中，最有可能在三個方面出現問題：
- 硬體配置
- 資料庫配置
- SQL語句
對於硬體配置來說，我們只能在解決了2和3的問題之後，再來評估到底多少硬體夠用的。而面對資料庫配置問題，這個實在沒什麼好招，只能去了解資料庫架構等一系列的知識之後，再學著解決。而SQL的問題呢，應該說是我們在效能測試和分析中最常見的了。SQL效能問題的分析思路也比較清晰，那就是判斷出具體的SQL瓶頸點，進而做相應的優化，切記不要蒙！
現在的資料庫類別比之前多太多了，每種資料庫都有自己的架構和使用場景，我們要在充分了解了之後，才能下手去調。