我們將要詳細的講到MySQL的剖析(Profiling),因為它很少依賴於你的應用。應用和服務器級別的剖析有的時候都是有必要的。雖然應用級別的剖析可以給你整個應用性能的總攬。,但是對MySQL的剖析提供了信息是服務器級別所提供不了的。比如,對PHP代碼進行剖析不會顯示MySQL有多少行語句執行了。
與應用剖析一樣,目標是找出MySQL哪部分消耗過多的時間。我們不會剖析MySQL源碼的,雖然有的時候定制化MySQL安裝很有用,但是這是另一本書的主題了。所替代的是,我們將教你一些可以技術來獲取和分析不同種類的MySQL執行語句的信息。
你可以用在任意的顆粒級別以滿足你的需求:你可能對整個服務器進行剖析或者單獨檢查一個語句或者一組語句。下列信息你可以一點點的收集:
MySQL有兩種記錄語句的類型:general log和slow log。他們都是記錄執行語句,但是卻在語句執行進程的兩端。general log記錄了每個服務器收到的語句,因此它的語句可能包含了那些沒有執行導致錯誤的語句。general Log記錄了所有的語句,包括了一些非執行語句的事件,比如連接和斷開連接。你可以用一個指令來啟用它。
log = <file_name>
根據設計,general log不會包括執行時間和其他一些僅僅在語句執行完畢的信息。相比較而言,slow log記錄執行完畢的語句。尤其是,它記錄那些超過指定時間執行的語句。這兩種日志都對程序剖析很有用,但是slow log是獲取問題語句的主要工具。我們常常推薦把它開啟。
下面列出的配置會開啟這個日志。獲取所有執行時間超過2s的語句,以及記錄那些不使用索引的語句。它也會記錄一些執行慢的管理語句,比如OPTIMIZE TABLE:
log-slow-querIEs = <file_name>
long_query_time = 2
log-querIEs-not-using-indexes
log-slow-admin-statements
你可以自定義這些配置,然後把它們放到my.conf文件中。更多的服務器配置將在以後的章節詳細講述。
long_query_time的默認值是10s。這個設置太慢了,因此我們一般都設置它為2s。然而,對於許多應用,可能1s都非常慢了。我們在下一部分將講述如何獲得顆粒度更細的日志。
在MySQL5.1中,提供了運行時調整slow_query_log,slow_query_log_file參數來控制slow log.但是在MySQL5.0中,在不啟動MySQL的情況下,不能開閉slow log。對於MySQL5.0的變通方法是,可以動態的修改long_query_time變量。下面的語句雖然不是真正開啟slow log的方式,但是取得了同樣的效果。(如果有語句執行超過了10000s,那麼你需要優化了這些語句了)
MySQL> SET GLOBAL long_query_time = 10000;
相關配置變量,log_querIEs_not_using_indexes 使服務器記錄沒有使用索引的語句。而不管它們的執行時間。雖然開啟了slow log會增加一些時間的消耗,導致語句執行速度減慢,但是沒有使用索引的語句還是可以經常和非常快速的執行。(比如一些查詢一些數據量小的表)這樣會使降低服務器的速度,以及使用大量的硬盤空間保存日志。
不幸的是,在MySQL5.0中不能動態的開啟或關閉日志。你必須修改MySQL配置文件,然後重啟MySQL。當你想關閉日志而不想重啟服務器,可以把日志文件做一個/dev/null的指向。在確定了MySQL關閉了日志文件描述以及在/dev/null重新打開它,那麼你僅執行FLUSH LOGS就可以了。
相比較而言,MySQL5.1能實時更改日志以及能把日志記錄到表中。這是個很大的進步了。
細顆粒度的日志
MySQL5.0以及更早的版本的slow log 都有一定的限制,在一些用途下就沒用了。最首要的問題就是它的顆粒度僅僅是秒。以及long_query_time在MySQL5.0中最小單位就是1s。大部分交互的應用中,這個時間就比較長了。如果你正在開發一個高性能的WEB應用,你可能希望整個頁面生成小於1s.以及在開始生成的過程中記錄許多語句。這種情況下,一個語句執行了150ms,也會被認為是個很慢的語句。
另一個問題是,並不是所有的執行語句都記錄在slow log中(尤其是,子節點的線程語句不能被記錄)。general log記錄了所有的語句,但是是在這些語句解析之前記錄的,只要就不能記錄一些如執行時間,鎖時間,以及執行的行數的記錄了。只有slow log包含這些信息。
最終,如果你開啟了log_querIEs_not_using_indexes參數。可能slow log就被大量的實體,高效的語句所填滿。比如,如果你過你生成一個下拉菜單的數據,你可能執行SELECT * FROM STATES。這個語句就被記錄了,因為它是整張表的掃描。
當程序剖析的目標是性能優化,你應該查看讓MySQL服務器大量工作的語句。這並不是意味著總是執行慢的語句。所以記錄執行慢的語句可能也沒什麼用處了。一個例子,一個10ms的語句在一秒內執行了1000次對服務器的壓力高於10s語句每秒運行一次。為了發現這個問題,你必須記錄每條語句和分析結果。
一起查看執行慢的語句和導致服務器壓力過大的語句執行總量是非常有用的方法。這會讓你發現不同的問題。如一個語句導致了很差的用戶體驗。
我們已經開發了一個MySQL的補丁。基於Georg Richter工作之上而開發的。讓你指定slow log語句時間到毫秒級別,而不是原來的秒。通過設置long_query_time=0,它也能讓你記錄所有的語句。這個補丁的地址是http://www.mysqlperformanceblog.com/mysql-patches/。它的主要缺點就是你需要自己編譯MySQL。因為這個補丁在MySQL5.1之前並沒有包含在MySQL發行包中。
目前,MySQL5.1包含了這個補丁,但僅能修改時間的顆粒度。這個補丁的新版本,將不會包含在MySQL的發行包中。新版本將添加一些有用的功能。這些功能包含了語句執行的連接ID,也包含了語句執行的緩存,連接類型,臨時表,以及排序。也添加了InnoDB的統計,比如I/O行為以及鎖等待。
新版本的補丁可以記錄子節點所執行的語句。如果在子節點復制的過程中出現問題,這個功能就尤其有用。它也能讓你選擇一些會話的日志。這些功能對程序剖析來說已經足夠了,我們認為這就是最佳實踐了。
這個補丁是比較新的,因此如果你要應用,要小心的使用它。我們想它已經很安全了,但是它在其他的MySQL服務器還沒有經過足夠的考驗。如果你擔心這個還有補丁的MySQL服務器的穩定性,你不一定要一直運行它,你可以先運行它幾個小時記錄一些語句,然後在恢復你自己的MySQL版本。
當程序剖析的時候,把參數long_query_time=0記錄所有語句是個很好的方法。如果大部分的讀取來自於非常簡單的語句,你可能想知道這些情況。記錄所有語句會影響一些性能以及它要求更多的硬盤空間-這就是另一個不需要記錄所有語句的理由。幸運的是,你可以隨時修改long_query_time而不用去重新啟動服務器。因此很容易在一段時間內獲取所有語句。然後在恢復記錄那些執行比較慢的語句。
怎樣讀取slow log這是一個slow log的例子
1 # Time: 030303 0:51:27
2 # User@Host: root[root] @ localhost []
3 # Query_time: 25 Lock_time: 0 Rows_sent: 3949 Rows_examined: 378036
4 SELECT ...
第一行顯示了日志記錄的時間,第二行顯示誰執行了這些語句。第三行顯示這語句執行的時間,在MySQL服務器級別等待表鎖的時間,執行語句返回的行數,以及語句檢索的行數。這些語句都是被注視掉的。因此如果你把日志提供給MySQL ClIEnt,他們也不會執行。最後一行就是執行的語句。
這個例子是MySQL5.1版本的
1 # Time: 070518 9:47:00
2 # User@Host: root[root] @ localhost []
3 # Query_time: 0.000652 Lock_time: 0.000109 Rows_sent: 1 Rows_examined: 1
4 SELECT ...
和上個日志基本相同,除了第三行,精度變得更高了。上一部分我們提到的補丁提供了更全面的信息
1 # Time: 071031 20:03:16
2 # User@Host: root[root] @ localhost []
3 # Thread_id: 4
4 # Query_time: 0.503016 Lock_time: 0.000048 Rows_sent: 56 Rows_examined: 1113
5 # QC_Hit: No Full_scan: No Full_join: No Tmp_table: Yes Disk_tmp_table: No
6 # Filesort: Yes Disk_filesort: No Merge_passes: 0
7 # InnoDB_IO_r_ops: 19 InnoDB_IO_r_bytes: 311296 InnoDB_IO_r_wait: 0.382176
8 # InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.067538
9 # InnoDB_pages_distinct: 20
10 SELECT ...
第五行顯示了這個語句是否使用了緩存,是否檢索了整張表,是否沒有用索引進行表連接,是否是否臨時表,以及臨時表是否創建在硬盤上。第六行給出了是否進行了文件排序以及,如果是,是否保存到硬盤上以及有多少合並排序通過它執行的。
如果語句執行在InnoDB上,第7,8,9行就會顯示。第7行顯示了在執行語句的時候,InnoDB計劃讀取的頁數,與它一起的是byte數值。第7行最後的一個值是InnoDB從硬盤讀取數據的時間。第8行顯示了語句等待行鎖以及用了多少時間等待進入InnoDB內核。
第9行顯示了語句訪問唯一InnoDB大約的頁面數。這個數值越大,准確度貌似就越低了。這個信息的一種用處就是估計在頁面中語句的工作集。這個就是InnoDB緩沖池緩存數據的方式。它也能顯示你的集群索引是非常的有用。如果這個語句的行很好的集群索引了,它們會填充更少的頁面。以後會講到集群索引。
使用slow log去解決慢語句並不總是很簡單。雖然log包含了很多有用的信息,但是一個非常重要的信息卻丟失了:那就是語句執行為什麼會這麼慢的一個想法。有的時候,這是顯而易見的。如果log得出了12,000,000行被檢查以及1,200,000被發送到了客戶端,你知道為什麼這麼慢的原因了--這是個很大的執行語句。然而,這是很難的的清晰。
要注意的是,不要給slow log添加過多的含義。如果你看到一條語句在log中出現多次,那就發現了這語句很慢以及需要優化。但是僅僅因為一個語句在log出現的頻率並不意味著它是個糟糕的語句或者甚至並不是緩慢的。你可能找到了一個很慢的語句,運行它,以及發現它執行的時間只是一眨眼的時間。出現在日志中只能說明在過去的那個時候這個語句執行時間很長,並不意味著現在或以後它會執行很長時間。一個語句有的時候很慢,在另外的時間卻很快,這種情況原因是很多的:
現在你已經記錄了一些執行的語句了。是時候分析結果了。一般的策略是找出對服務器影響最大的語句,用Explain檢查它們執行計劃進行必要的調整。在調整之後不斷地重復這個過程。因為你的修改可能會影響其他語句的執行。比較常見的就是索引可以提高SELECT的速度但是會降低INSERT或UPDATE語句。
一般來說你應該在日志中查找如下的執行語句: