天天看點

一個慢查詢報警的簡單處理

今天在做節後的一個基本檢查的時候,發現一個不太起眼的報警,報警内容為大體為:

MySQL 每秒慢查詢次數超過 <1>個on  xxxx

檢視zabbix的監控資料,發現每秒竟然有10個左右的慢查詢,按照這個量,這個資料庫得存在多大的問題啊。

一個慢查詢報警的簡單處理

是以覺得可能是在做一個全表掃描導緻的sql影響。

這個資料庫算是一個核心業務,而且負載一直不高,沒有收到任何關于IO,CPU,記憶體,swap的任何報警,一直在穩定運作,是以這是疑點之一。

這個庫因為很穩定,平時就是檢查基本的備份和基本的空間管理和日常的基本資料維護,而且也接手時間不長,是以很少去關注更多的内容,當我找到對應的資料目錄,發現一個問題,那就是這個慢日志檔案竟然有近60G

-rw-r--r-- 1 root  root  102M Feb  4 17:14 query.log

-rw-rw---- 1 mysql mysql  58G Feb 17 14:58 slow.log

一個慢日志如此龐大,這得暗示多大的性能問題啊,這是疑點之二。

當然如此龐大的日志檔案,我看看是從什麼時候積累起來的

# head -10 slow.log

# Time: 131114 13:41:59

# User@Host: app_new_bill[app_new_bill] @ xxxx_2.107 [xxxx]

# Thread_id: 131044  Schema: mobile_billing  Last_errno: 0  Killed: 0

# Query_time: 0.000648  Lock_time: 0.000129  Rows_sent: 28  Rows_examined: 58  Rows_affected: 0  Rows_read: 28

# Bytes_sent: 4235  Tmp_tables: 0  Tmp_disk_tables: 0  Tmp_table_sizes: 0

# InnoDB_trx_id: 1718382

SET timestamp=1384407719;

select app0_.id as id1_, app0_.appname as appname1_, app0_.appkey as appkey1_, app0_.appsecret as appsecret1_, app0_.iplist as iplist1_, app0_.isshow as isshow1_, app0_.flag as flag1_, app0_.test_version as test8_1_, app0_.create_date as create9_1_, app0_.game_type as game10_1_, app0_.callback_url as callback11_1_, app0_.iappay_id as iappay12_1_, app0_.isactivate as isactivate1_ from test_app app0_ where app0_.isshow=1 order by app0_.create_date desc;

# Time: 131114 13:42:01

看來這個日志積累自2013年了,是以幾年下來一直積累到了如此龐大。

當然我們需要馬上使用新的日志檔案,這個檔案就權當備份日志吧。使用mv修改日志名,然後使用mysqladmin flush-logs 重新整理日志,這樣新的日志内容就寫到slow.log裡面了。

切換之後的情況如下:

-rw-rw---- 1 mysql mysql    16195105 Feb 17 15:54 slow.log

-rw-rw---- 1 mysql mysql 61757873052 Feb 17 15:02 slow.log.bak

目前的慢查詢的配置是2秒的基線。

我們來看看慢查詢日志中的sql

# InnoDB_trx_id: 1B5249A5

SET timestamp=1455695652;

select * from tb_version_update where appkey='1400140930701' and media_channel_id='2014142002'  and take_effect_date < '2016-02-17 15:54:12' and is_take_effect=1 and isshow=1;

# User@Host: app_sdk_hero[app_sdk_hero] @ xxxx_128.100 [xxxx]

# Thread_id: 4537955  Schema: mobile_billing  Last_errno: 0  Killed: 0

# Query_time: 0.000570  Lock_time: 0.000072  Rows_sent: 0  Rows_examined: 158  Rows_affected: 0  Rows_read: 0

# Bytes_sent: 1753  Tmp_tables: 0  Tmp_disk_tables: 0  Tmp_table_sizes: 0

# InnoDB_trx_id: 1B5249A6

select * from tb_version_update where appkey='1400140930701' and media_channel_id='2010321003'  and take_effect_date < '2016-02-17 15:54:12' and is_take_effect=1 and isshow=1;

可以從這個日志看出,其實這個查詢的執行時間很短,肯定沒有達到慢查詢的觸發條件,不過根據執行計劃來看,确實沒有走索引。

而且關鍵的是相關的表隻有150多條記錄,實在也沒必要添加索引了吧,是以性能問題的可能性也不大。

這個時候有一個新的參數,也是跟同僚那兒取經所得。log_queries_not_using_indexes

# mysqladmin var|grep index

| expand_fast_index_creation                        | OFF    |

| fast_index_creation                               | ON     |

| innodb_adaptive_hash_index                        | ON     |

| innodb_adaptive_hash_index_partitions             | 8      |

| log_queries_not_using_indexes                     | ON     |

如果查詢沒有做索引,也會記錄到慢查詢之中,是以需要修改為off, set global log_queries_not_using_indexes =OFF即可。

然後就再也沒有這類的報警記錄了。

一個慢查詢報警的簡單處理

對于這個參數,預設值是off,是以一般也不會觸發這個問題。

官方對于這個參數的解釋如下:

<a href="http://dev.mysql.com/doc/refman/5.5/en/server-options.html#option_mysqld_log-queries-not-using-indexes">--log-queries-not-using-indexes</a>

Command-Line Format

--log-queries-not-using-indexes

System Variable

Name

<a href="http://dev.mysql.com/doc/refman/5.5/en/server-system-variables.html#sysvar_log_queries_not_using_indexes">log_queries_not_using_indexes</a>

Variable Scope

Global

Dynamic Variable

Yes

Permitted Values

Type

boolean

Default

OFF

關于慢查詢的解釋連結 http://dev.mysql.com/doc/refman/5.5/en/slow-query-log.html