mysql general_log解析_mysql的全量(查询)日志general-log的开启和分析方法

熟悉mysql的朋友应该都知道,error日志只记录数据库层的报错,binlog只记录增/删/改的记录,但是没记录谁执行,只记录执行用户名,slowlog虽然详细,但是只记录超过设定值的慢查询sql信息.

只有general-log才是记录所有的操作日志,不过他会耗费数据库5%-10%的性能,所以一般没什么特别需要,大多数情况是不开的,例如一些sql审计和不知名的排错等,那就是打开来使用了.

开启的方法

开启方法很简单,#先查看当前状态

mysql> show variables like 'general%';

+------------------+--------------------------------+

| Variable_name    | Value                          |

+------------------+--------------------------------+

| general_log      | OFF                            |

| general_log_file | /data/mysql/data/localhost.log |

+------------------+--------------------------------+

2 rows in set (0.00 sec)

#可以在my.cnf里添加,1开启(0关闭),当然了,这样要重启才能生效,有点多余了

general-log = 1

log = /log/mysql_query.log路径

#也可以设置变量那样更改,1开启(0关闭),即时生效,不用重启,首选当然是这样的了

set global general_log=1

#这个日志对于操作频繁的库,产生的数据量会很快增长,出于对硬盘的保护,可以设置其他存放路径

set global general_log_file=/tmp/general_log.log

然后就开启完了,看看是否有这个文件存在并产生了日志,我们看到localhost.log已经生成了,因为我是默认的,所以名字就是这样的.#ll

总用量 3215528

-rw-rw----. 1 mysql mysql         56 9月   5 11:32 auto.cnf

drwx------  2 mysql mysql       4096 9月  17 14:09 gw

-rw-rw----  1 mysql mysql      25666 9月   8 17:07 ib_buffer_pool

-rw-rw----. 1 mysql mysql 1073741824 9月  19 10:21 ibdata1

-rw-rw----. 1 mysql mysql 1073741824 9月  19 10:21 ib_logfile0

-rw-rw----. 1 mysql mysql 1073741824 9月   5 11:27 ib_logfile1

-rw-rw----  1 mysql mysql          5 9月   8 17:11 localhost.localdomain.pid

-rw-rw----  1 mysql mysql    6699602 9月  19 09:50 localhost.log

-rw-rw----  1 mysql mysql          5 9月  14 09:16 localhost.pid

drwx------. 2 mysql mysql       4096 9月   5 11:27 mysql

-rw-rw----  1 mysql mysql      34539 9月   7 14:57 mysql-bin.000006

-rw-rw----  1 mysql mysql   13746613 9月   8 17:07 mysql-bin.000007

-rw-rw----  1 mysql mysql     498989 9月  14 09:16 mysql-bin.000008

-rw-rw----  1 mysql mysql   48302055 9月  19 10:20 mysql-bin.000009

-rw-rw----  1 mysql mysql        136 9月  14 09:16 mysql-bin.index

-rw-rw----. 1 mysql mysql      57569 9月  14 09:16 mysql.err

drwx------. 2 mysql mysql       4096 9月   5 11:27 performance_schema

drwx------  2 mysql mysql       4096 9月  17 14:35 test

开启完了,就看怎么分析了.

分析日志

其实也比较直观,只是容易混淆,下面来看例子./usr/local/mysql/bin/mysqld, Version: 5.6.32-78.0-log (Percona Server (GPL), Release 78.0, Revision 8a8e016). started with:

Tcp port: 3306  Unix socket: /tmp/mysql.sock

Time                 Id Command    Argument

160919  9:28:19 30722 Connect   root@192.168.1.252 on test

30722 Query     SET SESSION sql_mode =

REPLACE(REPLACE(REPLACE(REPLACE(REPLACE(REPLACE(

@@sql_mode,

"STRICT_ALL_TABLES,", ""),

",STRICT_ALL_TABLES", ""),

"STRICT_ALL_TABLES", ""),

"STRICT_TRANS_TABLES,", ""),

",STRICT_TRANS_TABLES", ""),

"STRICT_TRANS_TABLES", "")

30722 Query     SET NAMES utf8

30722 Query     SELECT *

FROM `type`

WHERE `pid` = 30

30722 Quit

160919  9:28:38 29975 Query     SHOW GLOBAL STATUS

160919  9:28:39 30728 Connect   root@192.168.1.95 on test

30728 Query     SET SESSION sql_mode =

REPLACE(REPLACE(REPLACE(REPLACE(REPLACE(REPLACE(

@@sql_mode,

"STRICT_ALL_TABLES,", ""),

",STRICT_ALL_TABLES", ""),

"STRICT_ALL_TABLES", ""),

"STRICT_TRANS_TABLES,", ""),

",STRICT_TRANS_TABLES", ""),

"STRICT_TRANS_TABLES", "")

30728 Query     SET NAMES utf8

30728 Query     SELECT `a`.*, `b`.`clientname`, `b`.`deptname`, `b`.`receiveprovince`, `b`.`carriers`, `b`.`receivecity`

FROM `repri` as `a`

LEFT JOIN `illmain` as `b` ON `a`.`illid` = `b`.`illID`

WHERE `a`.`id` = '21'

30728 Query     SELECT `typename`

FROM `type`

WHERE `id` = '8'

30728 Query     SELECT `typename`

FROM `type`

WHERE `id` = '9'

30728 Query     SELECT *

FROM `handlepri`

WHERE `id` = '21'

30728 Query     SELECT *

FROM `low_re`

WHERE `low` = '21'

AND `type` =0

ORDER BY `id` desc

30728 Query     SELECT *

FROM `guide`

WHERE `ll_type` = '9'

30728 Query     SELECT *

FROM `illmain`

WHERE `illid` = '0992016'

OR `orderid` = '0992016'

30728 Quit

我们来按列来解析

第一列:时间列,前面一个是日期,后面一个是小时和分钟,有一些不显示的原因是因为这些sql语句几乎是同时执行的,所以就不另外记录时间了.

第二列:ID列,就是show processlist出来的第一列的线程ID,对于长连接和一些比较耗时的sql语句,你可以精确找出究竟是那一条那一个线程在运行.

第三列:操作类型,Connect就是连接数据库,Query就是查询数据库(增删查改都显示为查询),可以特定过虑一些操作.

第四列:详细信息,例如上面例子Connect的详细信息就是root@192.168.1.95 on test,意思就是root@192.168.1.95连上test库,如此类推,下面的意思就是30728这个线程号连上数据库之后,做了什么查询的操作.

还有其他一些grant/drop/create/alter等的操作,general_log都回全部记录下来,不过这里就不细细演示了,各位可以尝试一下.

最后,也正如我开始说的,有了这些信息,做sql语句审计就变得可能了,找到责任人也是没有压力的,而对于一些疑难杂症的sql分析也是很简单了.