23丨MySQL:資料庫級監控及常用計數器解析(下)
上一篇文章中,我們講了有關資料庫的全域性分析,那麼在今天的文章中,我們繼續看看在資料庫中,如何做定向分析。
還記得我在上篇文章中提到的工具嗎?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瓶頸點,進而做相應的優化,切記不要蒙!
現在的資料庫類別比之前多太多了,每種資料庫都有自己的架構和使用場景,我們要在充分了解了之後,才能下手去調。