MySQL日誌故障的處理和分析

有一臺預上線的服務器最近在做壓力測試，也引發了一系列的相關問題，排查思路可以提供參考。

問題的起因就是收到同事提醒，根據監控報警提示，磁盤空間滿了。上面有一個MySQL服務，現在已經寫入不了數據了。

>>create table test(id int);
ERROR 14 (HY000): Can't change size of file (Errcode: 28 - No space left on device)

碰到這類問題，直觀的思路就是查看分區下最大的文件，當然如果足夠智能，也可以啟用前幾天提到的故障自愈的實現思路。

當我切換到日誌目錄的時候，我發現慢日誌文件竟然有這麼大，都是百G級別。

-rw-r----- 1 mysql mysql 302365433856 Nov 7 07:55 slowquery.log

當時也是為了儘快的釋放慢日誌文件的空間，所以先是選擇了導出部分日誌到本地，作為後續的分析所用，然後清理了這個日誌文件。

系統層面是清理了文件，空間也可以通過du的方式看到是釋放了，但是使用df -h的方式卻不奏效，看起來是文件的句柄沒有正確釋放，在這種情況下，系統雖然釋放了不少的空間，但是數據庫層面還是寫入不了數據的。

這種情況該怎麼做，釋放句柄最好的一種方式就是重啟，但是顯然這不是一個好的方法，有些簡單暴力，有沒有更好的方案呢，我們來看看滿日誌相關的參數。

>show variables like '%slow%';
+-----------------------------------+------------------------------------+
| Variable_name | Value |
+-----------------------------------+------------------------------------+
| log_slow_admin_statements | OFF |
| log_slow_filter | |
| log_slow_rate_limit | 1 |
| log_slow_rate_type | session |
| log_slow_slave_statements | OFF |
| log_slow_sp_statements | ON |
| log_slow_verbosity | |
| max_slowlog_files | 0 |
| max_slowlog_size | 0 |
| slow_launch_time | 2 |
| slow_query_log | OFF |
| slow_query_log_always_write_time | 10.000000 |
| slow_query_log_file | /data/mysql_4350/log/slowquery.log |
| slow_query_log_use_global_control | |
+-----------------------------------+------------------------------------+

這裡我們可用的一個直接方式就是先關閉滿日誌，達到釋放句柄的目的，然後再次重啟開啟。

想明白了，操作就很簡單了。

>set global slow_query_log=off;
Query OK, 0 rows affected (6.54 sec)
>set global slow_query_log=on;
Query OK, 0 rows affected (0.00 sec)

很明顯，磁盤空間釋放了不少，對於慢日誌的問題分析，其中裡面有一個數據字典表存在大量的查詢請求，添加了索引之後，該問題得到了有效控制。

# df -h
Filesystem Size Used Avail Use% Mounted on
/dev/sda3 25G 5.5G 18G 24% /
tmpfs 31G 12K 31G 1% /dev/shm
/dev/sda1 190M 78M 103M 44% /boot
/dev/mapper/data-main
 717G 400G 281G 59% /data

這個問題剛過一會，又收到報警說磁盤空間又滿了，這次排除了慢日誌的影響，發現是審計日誌出了問題。

$ df -h
Filesystem Size Used Avail Use% Mounted on
/dev/sda3 25G 5.5G 18G 24% /
tmpfs 31G 12K 31G 1% /dev/shm
/dev/sda1 190M 78M 103M 44% /boot
/dev/mapper/data-main
 717G 609G 72G 90% /data

這裡需要說明的是，審計插件有幾類比較流行的，這裡用到的是Percona audit plugin,其實從性價比來說，這個插件的控制粒度還算比較粗，如果從控制的粒度來說，MariaDB Audit plugin要好很多，推薦使用。

審計日誌有差不多600G,在這種高壓測試之下，量級還是很大的，為了緩解問題，也是刪除了600G的審計日誌文件。

打開審計日誌的參數選項：

>show variables like '%audit%';
+-----------------------------+---------------+
| Variable_name | Value |
+-----------------------------+---------------+
| audit_log_buffer_size | 1048576 |
| audit_log_exclude_accounts | |
| audit_log_exclude_commands | |
| audit_log_exclude_databases | |
| audit_log_file | audit.log |
| audit_log_flush | OFF |
| audit_log_format | OLD |
| audit_log_handler | FILE |
| audit_log_include_accounts | |
| audit_log_include_commands | |
| audit_log_include_databases | |
| audit_log_policy | ALL |
| audit_log_rotate_on_size | 0 |
| audit_log_rotations | 0 |
| audit_log_strategy | ASYNCHRONOUS |
| audit_log_syslog_facility | LOG_USER |
| audit_log_syslog_ident | percona-audit |
| audit_log_syslog_priority | LOG_INFO |
+-----------------------------+---------------+
18 rows in set (0.01 sec)

這裡可以選的方式是修改審計日誌的策略，比如我們從ALL修改為NONE,但是這種方式還是有些侷限，因為沒有生效。到了這個時候可供選擇的方案就很少了，如果要釋放句柄，我們可以簡單先看看，比如通過lsof來查看未釋放的句柄。

# lsof|grep delete
mysqld 3218 mysql 5u REG 253,0 26946 85458954 /data/mysql_4350/tmp/ib6i5l8w (deleted)
mysqld 3218 mysql 6u REG 253,0 0 85458955 /data/mysql_4350/tmp/ibzgbLJz (deleted)
mysqld 3218 mysql 7u REG 253,0 0 85458956 /data/mysql_4350/tmp/ibUZDalC (deleted)
mysqld 3218 mysql 8u REG 253,0 0 85458960 /data/mysql_4350/tmp/ibhdSF1K (deleted)
mysqld 3218 mysql 12u REG 253,0 0 85458961 /data/mysql_4350/tmp/ibo46oDR (deleted)
mysqld 3218 mysql 41w REG 253,0 635612876075 85460307 /data/mysql_4350/data/audit.log (deleted)

但是很明顯這個進程就是MySQL服務的進程號，直接kill MySQL實在是太暴力了，而且這個測試還在進行中，為了避免不必要的解釋和麻煩，我們也是不能重啟數據庫的。

# ps -ef|grep 3218
mysql 3218 2015 22 Oct31 ? 1-14:53:02 /usr/local/mysql/bin/mysqld --basedir=/usr/local/mysql --datadir=/data/mysql_4350/data --plugin-dir=/usr/local/mysql/lib/mysql/plugin --user=mysql --log-error=/data/mysql_4350/log/mysql.err --open-files-limit=16384 --pid-file=/data/mysql_4350/tmp/mysql.pid --socket=/data/mysql_4350/tmp/mysql.sock --port=4350
root 87186 86999 0 15:20 pts/0 00:00:00 grep 3218

這裡有一個參數引起了我的注意，那就是audit_log_flush，有點類似於MySQL裡面的flush logs的方式。通過觸發這個參數就可以釋放已有的句柄了。

>set global audit_log_flush=on;
Query OK, 0 rows affected (10.04 sec)

通過幾輪問題分析和排查，日誌類的問題總算得到了基本解決。

後續需要改進的就是對於審計日誌的管理，目前做壓力測試其實是可以關閉這一類的審計的。

而對於慢日誌的分析也是重中之重，如果在極高的壓力下，差不多1~2分鐘會產生1G的慢日誌，按照併發來看，這個值是很高的。所以在基本穩定了性能之後，慢日誌的量級有了明顯的變化。