1. 程式人生 > >學會讀懂 MySql 的慢查詢日誌

學會讀懂 MySql 的慢查詢日誌

操作 get time user net 假死 幸運 存在 報錯

在前邊的博客《何時、怎樣開啟 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 的慢查詢日誌