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的慢日誌，按照併發來看，這個值是很高的。因此在基本穩定了性能以後，慢日誌的量級有了明顯的變化。