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的慢日志，按照并发来看，这个值是很高的。因此在基本稳定了性能以后，慢日志的量级有了明显的变化。