方法1. SHOW PROFILE
show profile是Mysql5.1版本之后引入的功能芦瘾。默認(rèn)是禁用的，但可以通過(guò)服務(wù)器變量在會(huì)話（連接）級(jí)別動(dòng)態(tài)修改逢勾。
mysql> SET profiling=1;
然后，在服務(wù)器上執(zhí)行的所有語(yǔ)句迫摔，都會(huì)測(cè)量其耗費(fèi)的時(shí)間和其他一些查詢執(zhí)行狀態(tài)變更相關(guān)的數(shù)據(jù)句占。這個(gè)工具功能非常強(qiáng)大纱烘，最有用的是在語(yǔ)句執(zhí)行期間剖析服務(wù)器的具體工作擂啥。
??工作原理：當(dāng)一條查詢提交給服務(wù)器時(shí)，show profile將記錄剖析信息到一張臨時(shí)表山宾，并且給查詢賦予一個(gè)從1開(kāi)始的整數(shù)標(biāo)志符资锰。
舉例說(shuō)明台妆，創(chuàng)建表shop，表結(jié)構(gòu)如下切厘。
mysql> show create table shop;
+-------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table | Create Table |
+-------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| shop | CREATE TABLE `shop` (
`id` int(11) NOT NULL AUTO_INCREMENT COMMENT '記錄ID',
`shop_id` int(11) NOT NULL COMMENT '商店ID',
`goods_id` int(11) NOT NULL COMMENT '物品ID',
`pay_type` tinyint(1) NOT NULL COMMENT '支付方式',
`price` decimal(10,2) NOT NULL COMMENT '物品價(jià)格',
`comment` varchar(4000) DEFAULT NULL,
PRIMARY KEY (`id`),
UNIQUE KEY `shop_id` (`shop_id`,`goods_id`),
KEY `price` (`price`),
KEY `pay_type` (`pay_type`)
) ENGINE=InnoDB AUTO_INCREMENT=20001 DEFAULT CHARSET=utf8 COMMENT='商店物品表' |
+-------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.01 sec)
預(yù)先插入兩萬(wàn)條數(shù)據(jù)遗座，然后執(zhí)行下面查詢俊扳。
mysql> select * from shop order by shop_id , goods_id limit 9;
[query results omitted]
9 rows in set (0.00 sec)
查詢返回9條結(jié)果途蒋，MySQL客戶端顯示的查詢時(shí)間只有兩位小數(shù)，對(duì)于一些執(zhí)行很快的查詢精度是不夠的馋记。下面看SHOW PROFILES的結(jié)果号坡。
mysql> show profiles;
+----------+------------+--------------------------------------------------------+
| Query_ID | Duration | Query |
+----------+------------+--------------------------------------------------------+
| 1 | 0.00059225 | select * from shop order by shop_id , goods_id limit 9 |
| 2 | 0.00007125 | shop profiles |
+----------+------------+--------------------------------------------------------+
2 rows in set (0.00 sec)
看到以更高的精度顯示查詢的響應(yīng)時(shí)間。繼續(xù)看接下來(lái)的輸出：
mysql> show profile cpu, block io for query 1;
+--------------------------------+----------+----------+------------+--------------+---------------+
| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+--------------------------------+----------+----------+------------+--------------+---------------+
| starting | 0.000029 | 0.000019 | 0.000009 | 0 | 0 |
| Waiting for query cache lock | 0.000009 | 0.000005 | 0.000004 | 0 | 0 |
| checking query cache for query | 0.000079 | 0.000077 | 0.000002 | 0 | 0 |
| checking permissions | 0.000014 | 0.000009 | 0.000003 | 0 | 0 |
| Opening tables | 0.000025 | 0.000023 | 0.000002 | 0 | 0 |
| System lock | 0.000014 | 0.000011 | 0.000003 | 0 | 0 |
| Waiting for query cache lock | 0.000036 | 0.000034 | 0.000001 | 0 | 0 |
| init | 0.000029 | 0.000027 | 0.000002 | 0 | 0 |
| optimizing | 0.000010 | 0.000007 | 0.000003 | 0 | 0 |
| statistics | 0.000014 | 0.000012 | 0.000002 | 0 | 0 |
| preparing | 0.000014 | 0.000011 | 0.000002 | 0 | 0 |
| executing | 0.000006 | 0.000004 | 0.000003 | 0 | 0 |
| Sorting result | 0.000009 | 0.000006 | 0.000002 | 0 | 0 |
| Sending data | 0.000178 | 0.000168 | 0.000010 | 0 | 0 |
| end | 0.000008 | 0.000005 | 0.000003 | 0 | 0 |
| query end | 0.000009 | 0.000006 | 0.000002 | 0 | 0 |
| closing tables | 0.000011 | 0.000033 | 0.000021 | 0 | 0 |
| freeing items | 0.000012 | 0.000013 | 0.000010 | 0 | 0 |
| Waiting for query cache lock | 0.000006 | 0.000008 | 0.000004 | 0 | 0 |
| freeing items | 0.000054 | 0.000000 | 0.000060 | 0 | 0 |
| Waiting for query cache lock | 0.000006 | 0.000002 | 0.000003 | 0 | 0 |
| freeing items | 0.000005 | 0.000002 | 0.000003 | 0 | 0 |
| storing result in query cache | 0.000006 | 0.000003 | 0.000002 | 0 | 0 |
| logging slow query | 0.000005 | 0.000003 | 0.000003 | 0 | 0 |
| cleaning up | 0.000007 | 0.000004 | 0.000002 | 0 | 0 |
+--------------------------------+----------+----------+------------+--------------+---------------+
25 rows in set (0.00 sec)
看到消耗時(shí)間最多是“發(fā)送數(shù)據(jù)（Sending data）”梯醒，且是CPU密集型宽堆。“Sending data”狀態(tài)含義很具有誤導(dǎo)性茸习，所謂的“Sending data”并不是單純的發(fā)送數(shù)據(jù)畜隶，而是包括“收集 + 發(fā)送 數(shù)據(jù)”。這里的關(guān)鍵是為什么要收集數(shù)據(jù)，原因在于：mysql使用“索引”完成查詢結(jié)束后察净，mysql得到了一堆的行id，如果有的列并不在索引中击碗，mysql需要重新到“數(shù)據(jù)行”上將需要返回的數(shù)據(jù)讀取出來(lái)返回給客戶端械拍。
??結(jié)合Sending data的定義迄损，將目標(biāo)聚焦在查詢語(yǔ)句的返回列上面绑谣，根據(jù)表結(jié)構(gòu)知道comment的內(nèi)容最大壤玫，把查詢語(yǔ)句的comment列去掉班缎，重新查詢一次：
mysql> select id,shop_id, goods_id, pay_type, price from shop order by shop_id , goods_id limit 9;
[query results omitted]
9 rows in set (0.00 sec)
下面重新看下SHOW PROFILES的結(jié)果趁耗。
mysql> show profiles;
+----------+------------+--------------------------------------------------------------------------------------------+
| Query_ID | Duration | Query |
+----------+------------+--------------------------------------------------------------------------------------------+
| 1 | 0.00059225 | select * from shop order by shop_id , goods_id limit 9 |
| 2 | 0.00007125 | shop profiles |
| 3 | 0.00054275 | select id,shop_id, goods_id, pay_type, price from shop order by shop_id , goods_id limit 9 |
+----------+------------+--------------------------------------------------------------------------------------------+
3 rows in set (0.00 sec)
mysql> show profile for query 3;
+--------------------------------+----------+
| Status | Duration |
+--------------------------------+----------+
| starting | 0.000030 |
| Waiting for query cache lock | 0.000011 |
| checking query cache for query | 0.000090 |
| checking permissions | 0.000011 |
| Opening tables | 0.000025 |
| System lock | 0.000014 |
| Waiting for query cache lock | 0.000039 |
| init | 0.000028 |
| optimizing | 0.000009 |
| statistics | 0.000013 |
| preparing | 0.000014 |
| executing | 0.000005 |
| Sorting result | 0.000009 |
| Sending data | 0.000127 |
| end | 0.000008 |
| query end | 0.000008 |
| closing tables | 0.000012 |
| freeing items | 0.000013 |
| Waiting for query cache lock | 0.000006 |
| freeing items | 0.000044 |
| Waiting for query cache lock | 0.000005 |
| freeing items | 0.000005 |
| storing result in query cache | 0.000006 |
| logging slow query | 0.000005 |
| cleaning up | 0.000006 |
+--------------------------------+----------+
25 rows in set (0.00 sec)
從上面的結(jié)果看到“Sending data”已經(jīng)由0.000178s降到0.000127s锄贷。
方法2. SHOW STATUS
show status 可以顯示mysql服務(wù)器的狀態(tài)岳锁，直接查詢status而不過(guò)濾乒躺，查詢出會(huì)有三百多條信息讳推。因此常用的方法是 show status like ‘%xxx%’ 進(jìn)行感興趣的狀態(tài)過(guò)濾。具體學(xué)習(xí)可以參考這篇文章：MySQL優(yōu)化：使用show status查看MySQL服務(wù)器狀態(tài)信息。
??使用SHOW STATUS摧找，排查出一個(gè)問(wèn)題芝雪，請(qǐng)查看拙作 MySQL server has gone away報(bào)錯(cuò)原因分析。
??下面這個(gè)方法實(shí)際就是以較高的頻率比如一秒執(zhí)行一次show global status命令來(lái)捕獲數(shù)據(jù)，通過(guò)某些計(jì)數(shù)器（比如 Threads_running妖胀、Threads_connected、Questions吼和、Queries）的變化來(lái)發(fā)現(xiàn)問(wèn)題。這三個(gè)數(shù)據(jù)的趨勢(shì)對(duì)于服務(wù)器級(jí)別偶爾停頓的敏感性很高安吁。一般發(fā)生此類(lèi)問(wèn)題，而其他兩個(gè)則至少有一個(gè)出現(xiàn)尖刺桨菜。
datou:~$ /usr/bin/mysqladmin ext -i1 -uroot -h127.0.0.01 |awk '/Queries/{q=$4-qp;qp=$4}/Threads_connected/{tc=$4}/Threads_running/{printf "%5d %5d %5d\n",q,tc,$4}'
144 2 1
1 2 1
1 2 1
1 2 1
1 2 1
1 2 1
1 2 1
方法3. SHOW PROCESSLIST
通過(guò)不停地捕獲 SHOW PROCESSLIST 的輸出，來(lái)觀察是否有大量線程處于不正常的狀態(tài)或者有其他不正常的特征菩彬。例如查詢很少會(huì)長(zhǎng)時(shí)間處于"statistics"狀態(tài)骗灶，這個(gè)狀態(tài)一般是指服務(wù)器在查詢優(yōu)化階段如何確定表關(guān)聯(lián)的順序--這通常都是非橙颇铮快的挨下。
??使用 SHOW PROCESSLIST 命令時(shí)，在尾部加上\G 可以垂直的方式輸出結(jié)果玷氏，這樣將每一行記錄的每一列都單獨(dú)輸出為一行堵未， 可以方便地使用 sort|uniq|sort 一類(lèi)的命令來(lái)計(jì)算某個(gè)列值出現(xiàn)的次數(shù)：
$ mysql -e 'SHOW PROCESSLIST\G' | grep State: | sort | uniq -c | sort -rn
744 State:
67 State: Sending data
36 State: freeing items
8 State: NULL
6 State: end
4 State: Updating
4 State: cleaning up
2 State: update
1 State: Sorting result
1 State: logging slow query
如果要查看不同的列，只需要修改grep 的模式即可盏触。在大多數(shù)案例中渗蟹，State 列都非常有用。從這個(gè)例子的輸出中看到赞辩，有很多線程處于查詢執(zhí)行的結(jié)束部分的狀態(tài)雌芽，包括"freeing items"、end"辨嗽、"cleaning up"和"logging slow query"世落。事實(shí)上，在案例中的這臺(tái)服務(wù)器上糟需，同樣模式或類(lèi)似的輸出采樣出現(xiàn)了很多次岛心。大量的線程處于"freeing items"狀態(tài)是出現(xiàn)了大量有問(wèn)題查詢的很明顯的特征和指示。
??上面的命令行不是唯一查找問(wèn)題方法篮灼。如果MySQL服務(wù)器的版本較新忘古，也可以直接查詢INFORMATION_SCHEMA 中的PROCESSLIST 表。上面演示的這個(gè)例子是由于InnoDB 內(nèi)部的爭(zhēng)用和臟塊刷新所導(dǎo)致诅诱，但有時(shí)候原因可能比這個(gè)要簡(jiǎn)單得多髓堪。
在processlist中，看到哪些運(yùn)行狀態(tài)時(shí)要引起關(guān)注，主要有下面幾個(gè)：
方法4. 使用慢查詢?nèi)罩?/h4>
方法4.1 修改mysql的配置文件my.cnf
查詢my.cnf文件路徑方法：
datou:/var/log/mysql$ which mysqld
/usr/sbin/mysqld
datou:/var/log/mysql$ /usr/sbin/mysqld --verbose --help |grep -A 1 'Default options'
[query results omitted]
Default options are read from the following files in the given order:
/etc/my.cnf /etc/mysql/my.cnf /usr/etc/my.cnf ~/.my.cnf
MySQL讀取各個(gè)my.cnf配置文件的先后順序是：
- /etc/my.cnf
- /etc/mysql/my.cnf
- /usr/etc/my.cnf
- ~/.my.cnf
按優(yōu)先級(jí)逐個(gè)排查/etc/my.cnf /etc/mysql/my.cnf /usr/etc/my.cnf ~/.my.cnf干旁，直到my.cnf文件存在驶沼。
在my.cnf文件[mysqld]里面加上以下內(nèi)容：
# Here you can see queries with especially long duration
slow_query_log_file = /var/log/mysql/mysql-slow.log # 日志位置
slow_query_log = 1 # 設(shè)置開(kāi)啟
long_query_time = 0.1 # 慢查詢超時(shí)記錄時(shí)間，單位 秒
# log_queries_not_using_indexes # 對(duì)沒(méi)有使用索引的查詢進(jìn)行記錄
重啟mysq： sudo service mysql restart争群，查看慢查詢配置是否生效使用下面的方法2回怜，配置生效后就可以在查詢中跟蹤慢查詢。
執(zhí)行查詢sql：
mysql> select * from shop where comment like '%a%' order by comment limit 9;
[query results omitted]
9 rows in set (0.21 sec)
看到mysql-slow.log輸出慢查詢?nèi)罩净槐。樵儠r(shí)間為0.211029s玉雾，與MySQL客戶端輸出的查詢時(shí)間一致。
yuejunzyj:/var/log/mysql$ cat /var/log/mysql/mysql-slow.log
/usr/sbin/mysqld, Version: 5.5.57-0ubuntu0.14.04.1-log ((Ubuntu)). started with:
Tcp port: 3306 Unix socket: /var/run/mysqld/mysqld.sock
Time Id Command Argument
# Time: 170915 11:43:48
# User@Host: root[root] @ localhost [127.0.0.1]
# Query_time: 0.211029 Lock_time: 0.000101 Rows_sent: 9 Rows_examined: 20009
use study;
SET timestamp=1505447028;
select * from shop where comment like '%a%' order by comment limit 9;
方法4.2 用命令開(kāi)啟慢查詢
mysql> show variables like "%long%"; //查看一下默認(rèn)為慢查詢的時(shí)間10秒
+-----------------+-----------+
| Variable_name | Value |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)
mysql> set global long_query_time=2; //設(shè)置成2秒轻要，加上global复旬，下次進(jìn)mysql生效
Query OK, 0 rows affected (0.00 sec)
mysql> show variables like "%slow%"; //查看一下慢查詢是不是已經(jīng)開(kāi)啟
+---------------------+---------------------------------+
| Variable_name | Value |
+---------------------+---------------------------------+
| log_slow_queries | OFF |
| slow_launch_time | 2 |
| slow_query_log | OFF |
| slow_query_log_file | /usr/local/mysql/mysql-slow.log |
+---------------------+---------------------------------+
4 rows in set (0.00 sec)
mysql> set slow_query_log='ON'; //加上global，不然會(huì)報(bào)錯(cuò)的冲泥。
ERROR 1229 (HY000): Variable 'slow_query_log' is a GLOBAL variable and should be set with SET GLOBAL
mysql> set global slow_query_log='ON'; //啟用慢查詢驹碍，下次進(jìn)mysql生效
Query OK, 0 rows affected (0.28 sec)
mysql> show variables like "%slow%"; //查看是否已經(jīng)開(kāi)啟
+---------------------+---------------------------------+
| Variable_name | Value |
+---------------------+---------------------------------+
| log_slow_queries | ON |
| slow_launch_time | 2 |
| slow_query_log | ON |
| slow_query_log_file | /usr/local/mysql/mysql-slow.log |
+---------------------+---------------------------------+
4 rows in set (0.00 sec)
