一、MySQL慢日誌分析工具方法

在日常運維中，經常需要開啟慢查詢日誌，可以讓MySQL記錄下查詢超過指定時間的語句，透過定位分析效能的瓶頸，更好的最佳化資料庫系統的效能。

那如何能更好更快的分析慢查詢日誌來協助我們分析並定位？官方提供了mysqldumpslow工具，也存在第三方工具如Mysqlsla及 pt-query-digest工具，下面分別介紹三個工具幫助運維人員瞭解並使用如上幾個工具。

1、Mysqldumpslow工具

Mysqldumpslow 是 Mysql自帶的一種慢日誌分析工具。可以使用該工具對慢日誌中所獲取到SQL進行一系列的統計與排序。

1.常用引數

常用引數	含義
-a	不將數字和字串抽象成N和S
-n	名稱中至少有N位數字的抽象數字
-g	只考慮與(grep樣式)模式匹配的查詢
--help	檢視幫助
-h	日誌檔名中伺服器的主機名
-i	伺服器例項的名稱
-l	不要從總時間中減去鎖時間
-r	反轉排序順序
-s	排序方式  -s t:按照總的查詢時間排序   -s at:按照平均查詢時間排序   -s l:按照總的鎖定時間排序   -s al:按照平均鎖定時間排序   -s s:按照總的記錄行數排序   -s as:按照平局的記錄行數排序   -s c:按照語句執行的次數排序,預設排序方式
-t	輸出前X行

2.範例

2.1 按照query time排序檢視日誌

mysqldumpslow -s t mysql-slow.log

2.2 按照平均query time排序檢視日誌

mysqldumpslow -s at mysql-slow.log

2.3 按照平均query time排序並且不抽象數字的方式排序

mysqldumpslow -a -s at mysql-slow.log

2.4 按照執行次數排序

mysqldumpslow -a -s c mysql-slow.log

2.5 按照執行次數排序,輸出一條sql

mysqldumpslow -s c -t 1  mysql-slow.log

3. 結果解析

Count: 3 Time=62.67s (188s) Lock=0.00s (0s) Rows=1623770.7 (4871312), root[root]@localhost
SELECT /*!N SQL_NO_CACHE */ * FROM `feed_receive_0287`
Count: 3                  該型別SQL語句執行次數3次
Time=62.67s (188s)        執行最長時間62.67s(3次總計執行時間188s)
Lock=0.00s (0s)           等待鎖的時間0s(3次總計等待鎖時間0s)
Rows=1623770.7 (4871312)  返回給客戶端行總數4871312/3=1623770.7行(3次共掃描行總數4871312次)
root[root]@localhost      連線使用者

2、Mysqlsla工具

Mysqlsla是一款幫助語句分析、過濾、分析和排序MySQL慢日誌、查詢日誌、二進位制日誌和microslow patched日誌的分析工具。整體來說, 功能非常強大。 資料包表,非常有利於分析慢查詢的原因, 包括執行頻率, 資料量, 查詢消耗等。是基於perl 寫的一個指令碼，專門用於處理分析Mysql的日誌而存在。

1.Mysqlsla軟體下載及安裝

下載:

GITHUB

百度雲盤

安裝：

1)安裝依賴

yum install  perl  perl-DBI  perl-DBD-MySQL perl-ExtUtils-CBuilder perl-ExtUtils-MakeMaker

2)安裝軟體

tar –xvf mysqlsla-2.03.tar.gz
perl Makefile.PL 
make
make install

2.常用引數

常用引數	含義
--log-type (-lt) TYPE LOGS	slow, general, binary, msl or udl
--sf	(+-)(TYPE)，(TYPE)有SELECT, CREATE, DROP, UPDATE, INSERT，不出現的預設是-，即不包括
--db	要處理哪個庫的日誌
--top	表示取按規則排序的前多少條
--sort	t_sum:按總時間排序(預設）；c_sum:按總次數排序；c_sum_p: sql語句執行次數佔總執行次數的百分比

3.範例

3.1 檢視幫助資訊

man mysqlsla

3.2 查詢慢日誌中最多的20個SQL語句

mysqlsla -lt slow --sort t_sum --top 20  /var/lib/mysql/log/mysql-slow.log

3.3有select和update查詢次數最多的10條SQL

mysqlsla -lt slow  -sf "+select,update" -top 10 -sort c_sum  -db mydata /var/lib/mysql/log/mysql-slow.log

3.4 查詢通用日誌查詢次數最多的10條SQL

mysqlsla -lt general  -top 10 -sort c_sum   /var/lib/mysql/log/mysql-general.log

4 結果解析

shell> mysqlsla -lt slow --sort t_sum --top 20  /var/lib/mysql/log/mysql-slow.log
Report for slow logs: /var/lib/mysql/log/mysql-slow.log
2 queries total, 2 unique
Sorted by 't_sum'
Grand Totals: Time 28 s, Lock 0 s, Rows sent 7, Rows Examined 6
________________________________________________________________001 ___
Count         : 1  (50.00%)
Time          : 22.596567 s total, 22.596567 s avg, 22.596567 s to 22.596567 s max  (81.88%)
Lock Time (s) : 170 µs total, 170 µs avg, 170 µs to 170 µs max  (100.00%)
Rows sent     : 6 avg, 6 to 6 max  (85.71%)
Rows examined : 6 avg, 6 to 6 max  (100.00%)
Database      : test
Users         : 
        root@localhost  : 100.00% (1) of query, 100.00% (2) of all users
Query abstract:
SET timestamp=N; SELECT sleep(N) FROM test;
Query sample:
SET timestamp=1574747237;
select sleep(4) FROM test;
________________________________________________________________002 ___
Count         : 1  (50.00%)
Time          : 5.001365 s total, 5.001365 s avg, 5.001365 s to 5.001365 s max  (18.12%)
Lock Time (s) : 0 total, 0 avg, 0 to 0 max  (0.00%)
Rows sent     : 1 avg, 1 to 1 max  (14.29%)
Rows examined : 0 avg, 0 to 0 max  (0.00%)
Database      : 
Users         : 
        root@localhost  : 100.00% (1) of query, 100.00% (2) of all users
Query abstract:
SET timestamp=N; SELECT sleep(N);
Query sample:
SET timestamp=1574746391;
select sleep(5);

總查詢次數 (queries total), 去重後的sql數量 (unique)

輸出報表的內容排序(sorted by)

最重大的慢sql統計資訊, 包括 平均執行時間, 等待鎖時間, 結果行的總數, 掃描的行總數.

Count, sql的執行次數及佔總的slow log數量的百分比.

Time, 執行時間, 包括總時間, 平均時間, 最小, 最大時間, 時間佔到總慢sql時間的百分比.

95% of Time, 去除最快和最慢的sql, 覆蓋率佔95%的sql的執行時間.

Lock Time, 等待鎖的時間.

95% of Lock , 95%的慢sql等待鎖時間.

Rows sent, 結果行統計數量, 包括平均, 最小, 最大數量.

Rows examined, 掃描的行數量.

Database, 屬於哪個資料庫

Users, 哪個使用者,IP, 佔到所有使用者執行的sql百分比

Query abstract, 抽象後的sql語句

Query sample, sql語句

3、 pt-query-digest工具

該工具已在前面章節介紹percona-toolkit運維工具中詳細介紹過，可自行往前翻閱

二、aborted告警日誌的分析 

在MySQL的error log中，我們會經常性看到一些各類的Aborted connection錯誤，本文中會針對這類錯誤進行一個初步分析，並瞭解一個問題產生後的基本排查思路和方法。

首先透過官方文件來了解Aborted_clients & Aborted_connects兩個狀態變數的代表意義，以及哪些情況或因素會導致這些狀態變數變化呢？

造成Aborted_connects狀態變數增加的可能原因：

1.客戶機試圖訪問資料庫，但沒有資料庫的特權。

2.客戶端使用了錯誤的密碼。

3.連線包不包含正確的資訊。

4.獲取一個連線包需要的時間超過connect_timeout秒。

造成Aborted_clients 狀態變數增加的可能原因：

1.程式退出前，客戶機程式沒有呼叫mysql_close()。

2.客戶端睡眠時間超過了wait_timeout或interactive_timeout秒

3.客戶端程式在資料傳輸過程中突然終止

簡單來說即：

資料庫會話未能正常連線到資料庫，會造成Aborted_connects變數增加。

資料庫會話已正常連線到資料庫但未能正常退出，會造成Aborted_clients變數增加。

2.測試案例

測試環境說明：MySQL5.7

測試環境及相關引數

connect_timeout	10
interactive_timeout	28800
wait_timeout	28800
max_connections	151
net_write_timeout	60
net_read_timeout	30

注：每次測試前均重啟資料庫重置狀態值，方便後續比較

+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| Aborted_clients  | 0     |
| Aborted_connects | 0     |
+------------------+-------+

測試一：錯誤密碼、錯誤使用者

shell> mysql -uroot -perrorpass -S/tmp/mysql57.sock
ERROR 1045 (28000): Access denied for user 'root'@'localhost' (using password: YES)
shell> mysql -uroot -perrorpass -h127.0.0.1 -P3307
ERROR 1045 (28000): Access denied for user 'root'@'localhost' (using password: YES)
錯誤使用者：
shell> mysql –uroot1 -perrorpass -S/tmp/mysql57.sock  
ERROR 1045 (28000): Access denied for user 'root'@'localhost' (using password: YES)

檢視資料庫內狀態值

+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| Aborted_clients  | 0     |
| Aborted_connects | 3     |
+------------------+-------+

檢視錯誤日誌

2019-11-20T22:03:31.226480Z 3 [Note] Access denied for user 'root'@'localhost' (using password: YES)
2019-11-20T22:04:14.420560Z 4 [Note] Access denied for user 'root'@'localhost' (using password: YES)
2019-11-20T22:04:32.670073Z 5 [Note] Access denied for user 'root1'@'localhost' (using password: YES)

測試二：超時引數

當前資料庫wait_timeout 及interactive_timeout均為預設的28800，下面調整這兩個引數，測試對資料庫連線的行為影響。

該實驗同時修改兩個引數為10

mysql> set global wait_timeout=10;

mysql> set global interactive_timeout=10;

------等待一段時間之後-----

mysql> show processlist;
ERROR 2006 (HY000): MySQL server has gone away
No connection. Trying to reconnect...
Connection id:    4
Current database: *** NONE ***
+----+------+-----------+------+---------+------+----------+------------------+
| Id | User | Host      | db   | Command | Time | State    | Info             |
+----+------+-----------+------+---------+------+----------+------------------+
|  4 | root | localhost | NULL | Query   |    0 | starting | show processlist |
+----+------+-----------+------+---------+------+----------+------------------+
1 row in set (0.00 sec)

檢視資料庫內狀態值

+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| Aborted_clients  | 2     |
| Aborted_connects | 0     |
+------------------+-------+

檢視錯誤日誌

2019-11-20T23:29:04.012321Z 3 [Note] Aborted connection 3 to db: 'unconnected' user: 'root' host: 'localhost' (Got timeout reading communication packets)
2019-11-20T23:29:37.137417Z 4 [Note] Aborted connection 4 to db: 'unconnected' user: 'root' host: 'localhost' (Got timeout reading communication packets)

測試三：最大連線數

當前資料庫max_connections引數預設為151，下面調整改引數，測試對資料庫連線的行為影響。

mysql> set global max_connections=2;

當開啟第四個連線會話，報如下錯誤：

shell> mysql57
ERROR 1040 (HY000): Too many connections

檢視資料庫內狀態值

+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| Aborted_clients  | 0     |
| Aborted_connects | 0     |
+------------------+-------+

此時錯誤日誌無變化。

測試四：第三方工具SQLyog select結果沒有出來的時候選擇停止則出現

SELECT SLEEP(10);

檢視資料庫內狀態值

+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| Aborted_clients  | 1     |
| Aborted_connects | 0     |
+------------------+-------+

此時錯誤日誌無變化。

結論：

1.建議業務操作結束後使應用程式邏輯以正確關閉連線，以短連線替代長連線

2.確保max_allowed_packet的值足夠高，並且客戶端沒有收到“資料包太大”訊息

3.確保客戶端應用程式不中止連線。

4.檢查是否啟用了skip-name-resolve，檢查主機根據其IP地址而不是其主機名進行身份驗證

5.嘗試增加MySQL的net_read_timeout和net_write_timeout值，看看是否減少了錯誤的數量