SQL - MySQL Server 日常維護: Log 分析(mysqlsla)

MySQL Server 日常維護: Log 分析(mysqlsla)

在之前的文章中已有提過如何利用 mysqlreport 這套工具來掌握 MySQL 目前的運作狀況(MySQL 效能監控工具--mysqlreport)，它可以協助我們瞭解 MySQL Server 的健康狀況以及 MySQL Server 大部份時間在處理什麼類型的 Query，但還有一個關鍵的問題沒有回答，就是在那些特定類型的 Query 中，MySQL 實際上到底是把 CPU 運算時間花在哪些 Query 上？若想要回答這個問題就必須要分析 MySQL 的 Log 才能得知。

大致上來說，MySQL 提供三大類的 LOG：

1. Binary Log：記錄所有對於資料庫的修改操作
2. General Log：記錄所有 Client 發送到 Server 的 Query
3. Slow Log：記錄所有的 Slow Query

藉由分析 General Log，我們可以清楚的得知 MySQL Server 最常執行的 Query 有哪些；觀察 Slow Log 則可以讓我們得知到底是哪些 Query 造成 MySQL Server 效能低落。知道了這些資訊以後我們才有辦法對 MySQL Server 進行進一步的調整與最佳化，例如以適當的 Index 提高 MySQL 最常執行的 Query 的效率，或是去除造成 Slow Query 的成因(poor index, join...等)。視您的 MySQL Server 的忙錄狀態而定，您的 General Log(或 Slow Log) 有可能會非常的龐大，要以肉眼來分析是一項不可能的任務，比較實際的作法是自己撰寫 Scripts 去進行 Log 分析。若您不想花時間自行開發程式，不妨試試由 Daniel Nichter 所提供的 mysqlsla。

官方網站： http://hackmysql.com/
軟體下載： http://hackmysql.com/mysqlsla

Log 分析步驟：

1. 開啟 MySQL Server 的 General Log 與 Slow Log
2. 以 mysqlsla 分析 Log 檔案
3. 解讀報表

MySQL Server Log 分析

一、開啟 MySQL Server 的 General Log 與 Slow Log

要分析 Log 檔案之前，你當然要先有可以分析的 Log 檔案。要開啟 MySQL Server 的 General Log 與 Slow Log，需要修改 MySQL Server 的系統設定檔並重新啟動 MySQL。

引用:

/etc/my.cnf：
[mysqld]
log=general-log
log-slow-queries=slow-log

重新啟動 MySQL Server 後，您應該會在 MySQL 的 Data Dir 裡面發現 general-log 與 slow-log 這二個檔案。請注意，MySQL Server 的 General Log 與 Slow Log 預設不會進行 Logrotate，因此您要記得自己處理這個部份，不然的話只要你的 Server 夠忙錄， General Log 可能會用光你所有的硬碟空間。例如在 Linux 系統中可以在 /etc/logrotate.d 中加上 mysqld 檔案，內容為：

引用:

/var/log/mysqld.log /var/lib/mysql/general-log /var/lib/mysql/slow-log {
missingok
notifempty
sharedscripts
postrotate
/usr/bin/mysqladmin flush-logs
endscript
}

二、以 mysqlsla 分析 Log 檔案

mysqlsla 其實是一支 Perl Scripts，使用方式很間單，語法如下：

A. 分析 General Log

引用:

mysqlsla -u root -p --flat --general general-log

--flat: 表示分析 Query 的時候把它們全部轉為小寫，也就是說大小寫的差異不列入考量

--general： 表示要分析的是 General Log

general-log： 這裡要填入 general-log 檔案名稱，若有多個 Log 檔案請使用逗號分隔，例如 log1,log2...

所產生的範例報表如下：（mysqlsla 預設只會列出 Top 10 Query）

PHP 語法:

<!---->Reading general log 'general-log'.
1926707 total queries, 4085 unique.
Sorting by 'c'.

__ 001 _______________________________________________________________________

Count         : 291423 (15%)
Database      : example

Query 1.....

__ 002 _______________________________________________________________________

Count         : 271380 (14%)
Database      : example

Query 2.....

__ 003 _______________________________________________________________________

Count         : 193304 (10%)
Database      : example

Query 3.....

__ 004 _______________________________________________________________________

Count         : 172429 (9%)
Database      : example

Query 4.....

__ 005 _______________________________________________________________________

Count         : 132067 (7%)
Database      : example

Query 5.....

__ 006 _______________________________________________________________________

Count         : 112499 (6%)
Database      : example

Query 6.....

__ 007 _______________________________________________________________________

Count         : 84409 (4%)
Database      : example

Query 7.....

__ 008 _______________________________________________________________________

Count         : 65973 (3%)
Database      : example

Query 8.....

__ 009 _______________________________________________________________________

Count         : 40396 (2%)
Database      : example

Query 9.....

__ 010 _______________________________________________________________________

Count         : 38702 (2%)
Database      : example

Query 10..... 
<!---->

然後您就可以大致上瞭解 Server 都在處理些什麼東西。



B. 分析 Slow Log

引用:

mysqlsla -u root -p --flat --slow --ex --db 資料庫名稱 slow-log

引用:

--flat: 表示分析 Query 的時候把它們全部轉為小寫，也就是說大小寫的差異不列入考量

--slow： 表示要分析的是 Slow Log

--ex： 使用 EXPLAIN 分析 Query

--db 資料庫名稱：Slow Log 不一定會記錄 Query 所屬的 Database，這樣一來當 Server 要進行 EXPLAIN 時會有問題，因此在這裡我們自己指定所使用的 Database。

slow-log： 這裡要填入 slow-log 檔案名稱，若有多個 Log 檔案請使用逗號分隔，例如 log1,log2...。

所產生的範例報表如下：（mysqlsla 預設只會列出 Top 10 Query）

PHP 語法:

<!---->Reading slow log 'slow-log'.
160 total queries, 21 unique.
Databases for Unknown: example 
Sorting by 't'.

__ 001 _______________________________________________________________________

Count         : 75 (46%)
Time (seconds): 1449 total, 19.32 avg, 12 to 26 max
95% of Time   : 1348 total, 18.99 avg, 12 to 25 max
Lock (seconds): 445 total, 5.93 avg, 0 to 13 max
Rows sent     : 247 avg, 92 to 250 max
Rows examined : 39787 avg, 27136 to 53228 max
User          : example[example]@localhost/ (76%)
Database      : example
Rows (EXPLAIN): 24494 produced, 24494 read
EXPLAIN       : 
id: 1
select_type: SIMPLE
table: SAMPLE
type: ref
possible_keys: SAMPLE
key: SAMPLE
key_len: 4
ref: const,const
rows: 24494
Extra: Using where; Using filesort


Query1 ..........

__ 002 _______________________________________________________________________

Count         : 4 (2%)
Time (seconds): 659 total, 164 avg, 164 to 166 max
95% of Time   : 493 total, 164 avg, 164 to 165 max
Lock (seconds): 0 total, 0 avg, 0 to 0 max
Rows sent     : 53871729 avg, 53792839 to 53954842 max
Rows examined : 53871729 avg, 53792839 to 53954842 max
User          : example[example]@localhost/ (23%)
Database      : example
Rows (EXPLAIN): 54003520 produced, 54003520 read
EXPLAIN       : 
id: 1
select_type: SIMPLE
table: SAMPLE
type: ALL
possible_keys: 
key: 
key_len: 
ref: 
rows: 54003520
Extra: 


Query2 ..........

__ 003 _______________________________________________________________________

Count         : 30 (18%)
Time (seconds): 412 total, 13.73 avg, 6 to 29 max
95% of Time   : 355 total, 12.68 avg, 6 to 28 max
Lock (seconds): 0 total, 0 avg, 0 to 0 max
Rows sent     : 20475 avg, 3889 to 77241 max
Rows examined : 20475 avg, 3889 to 77241 max
User          : example[example]@localhost/ (76%)
Database      : example
Rows (EXPLAIN): 27060 produced, 27060 read
EXPLAIN       : 
id: 1
select_type: SIMPLE
table: SAMPLE
type: ref
possible_keys: SAMPLE
key: SAMPLE
key_len: 3
ref: const
rows: 27060
Extra: 


Query3 ..........

__ 004 _______________________________________________________________________

Count         : 20 (12%)
Time (seconds): 219 total, 10.95 avg, 10 to 12 max
95% of Time   : 207 total, 10.89 avg, 10 to 12 max
Lock (seconds): 0 total, 0 avg, 0 to 0 max
Rows sent     : 0 avg, 0 to 1 max
Rows examined : 1077422 avg, 1076385 to 1078557 max
User          : example[example]@localhost/ (23%)
Database      : example
Rows (EXPLAIN): 1078830 produced, 3236490 read
EXPLAIN       : 
id: 1
select_type: PRIMARY
table: SAMPLE
type: index
possible_keys: SAMPLE
key: SAMPLE
key_len: 8
ref: 
rows: 1078830
Extra: Using where; Using index; Using temporary; Using filesort

id: 3
select_type: DEPENDENT SUBQUERY
table: SAMPLE
type: ref
possible_keys: SAMPLE
key: SAMPLE
key_len: 2
ref: const
rows: 1
Extra: Using where

id: 2
select_type: DEPENDENT SUBQUERY
table: SAMPLE
type: unique_subquery
possible_keys: PRIMARY,forumid
key: PRIMARY
key_len: 4
ref: func
rows: 1
Extra: Using index; Using where


Query4 ..........

__ 005 _______________________________________________________________________

Count         : 4 (2%)
Time (seconds): 75 total, 18.75 avg, 16 to 22 max
95% of Time   : 53 total, 17.67 avg, 16 to 19 max
Lock (seconds): 0 total, 0 avg, 0 to 0 max
Rows sent     : 1077174 avg, 1076128 to 1078321 max
Rows examined : 1077174 avg, 1076128 to 1078321 max
User          : example[example]@localhost/ (23%)
Database      : example
Rows (EXPLAIN): 1078830 produced, 1078830 read
EXPLAIN       : 
id: 1
select_type: SIMPLE
table: SAMPLE
type: ALL
possible_keys: 
key: 
key_len: 
ref: 
rows: 1078830
Extra: 


Query5 ..........

__ 006 _______________________________________________________________________

Count         : 4 (2%)
Time (seconds): 40 total, 10 avg, 10 to 10 max
95% of Time   : 30 total, 10.00 avg, 10 to 10 max
Lock (seconds): 0 total, 0 avg, 0 to 0 max
Rows sent     : 2207544 avg, 2205402 to 2209884 max
Rows examined : 2207544 avg, 2205402 to 2209884 max
User          : example[example]@localhost/ (23%)
Database      : example
Rows (EXPLAIN): 2211096 produced, 2211096 read
EXPLAIN       : 
id: 1
select_type: SIMPLE
table: SAMPLE
type: ALL
possible_keys: 
key: 
key_len: 
ref: 
rows: 2211096
Extra: 


Query6 ..........

__ 007 _______________________________________________________________________

Count         : 4 (2%)
Time (seconds): 36 total, 9 avg, 9 to 9 max
95% of Time   : 27 total, 9.00 avg, 9 to 9 max
Lock (seconds): 0 total, 0 avg, 0 to 0 max
Rows sent     : 0 avg, 0 to 0 max
Rows examined : 1827 avg, 1826 to 1828 max
User          : example[example]@localhost/ (23%)
Database      : example
Rows (EXPLAIN): 3656396 produced, 3658344 read
EXPLAIN       : 
id: 1
select_type: PRIMARY
table: SAMPLE
type: ref
possible_keys: SAMPLE
key: SAMPLE
key_len: 2
ref: const
rows: 1948
Extra: Using where

id: 2
select_type: DEPENDENT SUBQUERY
table: SAMPLE
type: ref
possible_keys: SAMPLE
key: award_id
key_len: 2
ref: const
rows: 1877
Extra: Using where


Query7 ..........

__ 008 _______________________________________________________________________

Count         : 2 (1%)
Time (seconds): 36 total, 18 avg, 13 to 23 max
95% of Time   : 13 total, 13.00 avg, 13 to 13 max
Lock (seconds): 6 total, 3 avg, 1 to 5 max
Rows sent     : 250 avg, 250 to 250 max
Rows examined : 45386 avg, 40636 to 50136 max
User          : example[example]@localhost/ (76%)
Database      : example
Rows (EXPLAIN): 24494 produced, 24494 read
EXPLAIN       : 
id: 1
select_type: SIMPLE
table: SAMPLE
type: ref
possible_keys: SAMPLE
key: SAMPLE
key_len: 4
ref: const,const
rows: 24494
Extra: Using where; Using filesort


Query8 ..........

__ 009 _______________________________________________________________________

Count         : 3 (1%)
Time (seconds): 30 total, 10 avg, 6 to 12 max
95% of Time   : 18 total, 9.00 avg, 6 to 12 max
Lock (seconds): 1 total, 0.33 avg, 0 to 1 max
Rows sent     : 0 avg, 0 to 0 max
Rows examined : 0 avg, 0 to 0 max
User          : example[example]@localhost/ (76%)
Database      : Unknown
Rows (EXPLAIN): EXPLAIN error: Not a SELECT statement.
EXPLAIN       : EXPLAIN error: Not a SELECT statement.

Query9 ..........

__ 010 _______________________________________________________________________

Count         : 3 (1%)
Time (seconds): 21 total, 7 avg, 6 to 8 max
95% of Time   : 13 total, 6.50 avg, 6 to 7 max
Lock (seconds): 0 total, 0 avg, 0 to 0 max
Rows sent     : 143522 avg, 121334 to 187844 max
Rows examined : 143522 avg, 121334 to 187844 max
User          : example[example]@localhost/ (76%)
Database      : example
Rows (EXPLAIN): 141085 produced, 141085 read
EXPLAIN       : 
id: 1
select_type: SIMPLE
table: SAMPLE
type: ref
possible_keys: SAMPLE
key: SAMPLE
key_len: 3
ref: const
rows: 141085
Extra: Using index


Query10 .......... 
<!---->

有了這些資訊後，下一步就是要進行 Query 的最佳化，與 Server 系統參數的調校。