今天在做節後的一個基本檢查的時候,發現一個不太起眼的報警,報警内容為大體為:
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