學會讀懂 MySql 的慢查詢日誌

標籤：iss   解決   sdn   tracking   details   慢查詢   font   http   時間   

在前邊的部落格《何時、怎樣開啟 MySql 日誌？》中，我們瞭解到了怎樣啟用 MySql 的慢查詢日誌。

今天我們來看一下怎樣去讀懂這些慢查詢日誌。
在跟蹤慢查詢日誌之前。首先你得保證最少發生過一次慢查詢。假設你沒有能夠自己製造一個：
[email protected]# mysql -e ‘SELECT SLEEP(8);
上述操作所做的事情僅僅有一個："睡"(啥也不做)八秒。這個長度應該足以被記錄在你的慢查詢日誌裡了(我通常推薦針對長於 2 或 3 秒的查詢進行慢查詢記錄)。
首先，我們看看一個慢速查詢日誌條目是什麼樣子的：
[email protected]# tail /var/log/slowqueries
# Time: 130320  7:30:26
# [email protected]: db_user[db_database] @ localhost []
# Query_time: 4.545309  Lock_time: 0.000069 Rows_sent: 219  Rows_examined: 254
SET timestamp=1363779026;
SELECT option_name, option_value FROM wp_options WHERE autoload = ‘yes‘;
我們來過一下每一行所代表的意思：

• 第一行表示記錄日誌時的時間。其格式是 YYMMDD H:M:S。我們能夠看出上面的查詢記錄於 2013 年 3 月 20 日上午 7:30 - 注意：這個是server時間，可能跟你本地時間有所不同
• 然後，我們能夠看到 MySql 使用者、server以及主機名稱
• 第三行表示總的查詢時間、鎖定時間、"發送"或者返回的行數、查詢過程中所檢查的行數
• 接下來我們看到的是 SET timestamp=UNIXTIME; 這是查詢實際發生的時間。假設你想找如今的一些慢查詢。通過檢查這個就不會發生你所檢查的是幾個月之前所發生的慢查詢了。下邊我會介紹怎樣將其變成一個實用的時間
• 最後一行顯示完整的查詢語句

要將 Unix 時間轉成一個人類可讀的時間，能夠使用 date -d 命令。

輸入 date -d @(記得要包含 @ 符號)，然後在 @(之間沒有空格)後粘貼日誌中的時間戳記：
[email protected]# date -d @1363779026
Wed Mar 20 07:30:26 EDT 2013
上面範例中我們能夠看到查詢進行的同一時候記錄了該日誌 - 可是對於一台超負載的server經常並不是如此。

因此記住：SET timestamp= value 才是實際的查詢的執行時間。

如今我來示範一下我是怎樣使用 MySql 慢查詢日誌來解決我的某個網站上的一個真實問題的。

你的查詢可能與此不太一樣，可是解決這個問題的原理是相通的。

我在一個部落格網站上使用了一個名為 Tweet Blender 的外掛程式來自己主動顯示相關微博到我的keyword中。不幸的是，一些人發現了這個並使用我的微博中的keyword來發一些垃圾微博 - 無論怎樣，終於結果就是我的部落格網站上顯示的是一些垃圾微博。

由於相關微博在我的網站存在的時間並不長，所以我在網站上並沒有發現什麼問題。直到我查看慢查詢日誌。
我的網站對帶有垃圾資訊(垃圾資訊經常都是一樣的)的微博進行了幾個相似的查詢，經過一段時間後這些查詢的數量太大以致當中的一些執行遲緩。

當這樣的情況發生的時候，由於請求的數量非常大，有些朋友的網站非常可能會因此假死或者直接報錯。可是我的server經過非常好的效能調優，因此並沒有非常明顯的影響。幸運的是當時我進行中慢查詢日誌查看。及時發現了這一情況並迅速攻克了這個問題。
這個問題的解決非常easy - Tweet Blender 具備一個美麗的過濾功能。我僅僅需將該微博username以及一些垃圾keyword加入到 "exclude" 列表。之後就再也沒有這樣的問題了。這樣看來，對我們自己網站以及日誌的監控是多麼重要，即使是一星期對每一個網站/server僅僅進行一次高速檢查。

原文連結：http://calladeveloper.blogspot.com/2013/03/howto-read-mysql-slow-query-log.html。

學會讀懂 MySql 的慢查詢日誌