Mysql日志详解
错误日志
错误日志会记录如下信息
- mysql执行过程中的错误信息
- mysql执行过程中的告警信息
- event scheduler运行时所产生信息
- mysq启动和停止过程中产生的信息
- 主从复制结构中，重从服务器IO复杂线程的启动信息
错误日志相关参数
MariaDB [(none)]> show variables where
-> variable_name="log_error" or
-> variable_name="log_warnings";
+---------------+------------------------------------------------------+
| Variable_name | Value |
+---------------+------------------------------------------------------+
| log_error | D:\application\MariaDB 10.4\data\DESKTOP-A3DGD26.err |
| log_warnings | 2 |
+---------------+------------------------------------------------------+
2 rows in set (0.001 sec)
log_error：错误日志的存放路径
log_warnings：表示是否记录告警信息到错误日志，0表示不记录告警信息，1表示记录告警信息，大于1表示各类告警信息，例如有关网络故障的信息和重新连接信息写入错误日志
FILE：
InnoDB: using atomic writes. 2019-09-05 19:32:27 0 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions 2019-09-05 19:32:27 0 [Note] InnoDB: Uses event mutexes 2019-09-05 19:32:27 0 [Note] InnoDB: Compressed tables use zlib 1.2.11 2019-09-05 19:32:27 0 [Note] InnoDB: Number of pools: 1 2019-09-05 19:32:27 0 [Note] InnoDB: Using SSE2 crc32 instructions 2019-09-05 19:32:27 0 [Note] InnoDB: Initializing buffer pool, total size = 1G, instances = 1, chunk size = 128M 2019-09-05 19:32:27 0 [Note] InnoDB: Completed initialization of buffer pool 2019-09-05 19:32:27 0 [Note] InnoDB: 128 out of 128 rollback segments are active. 2019-09-05 19:32:27 0 [Note] InnoDB: Creating shared tablespace for temporary tables 2019-09-05 19:32:27 0 [Note] InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 2019-09-05 19:32:27 0 [Note] InnoDB: File '.\ibtmp1' size is now 12 MB. 2019-09-05 19:32:27 0 [Note] InnoDB: Waiting for purge to start 2019-09-05 19:32:27 0 [Note] InnoDB: 10.4.7 started; log sequence number 139854; transaction id 21 2019-09-05 19:32:27 0 [Note] InnoDB: Loading buffer pool(s) from D:\application\MariaDB 10.4\data\ib_buffer_pool 2019-09-05 19:32:27 0 [Note] Plugin 'FEEDBACK' is disabled. 2019-09-05 19:32:27 0 [Note] Server socket created on IP: '::'. 2019-09-05 19:32:28 0 [Note] InnoDB: Buffer pool(s) load completed at 190905 19:32:28 2019-09-05 19:32:28 0 [Note] Reading of all Master_info entries succeeded 2019-09-05 19:32:28 0 [Note] Added new Master_info '' to hash table 2019-09-05 19:32:28 0 [Note] D:\application\MariaDB 10.4\bin\mysqld.exe: ready for connections. Version: '10.4.7-MariaDB' socket: '' port: 3306 mariadb.org binary distribution 2019-09-05 19:35:47 8 [Warning] Access denied for user '13098884691'@'localhost' (using password: NO)
查询日志
查询自然在mysql中被称之为general log，查询日志记录了数据库执行的命令，不管这些语法是否正确，都会被记录。由于数据库操作命令非常多而且比较频繁，
所以开启了查询日志以后，数据库可能需要不停的写入查询，这样会增大服务器的IO压力，增加很多的系统开销，所以默认情况下，mysql的查询日志是没有开启
的，但是开启查询日志也有助于我们分析那些语句执行密集，执行密集的select语句对应的数据是否能够被缓存，查询日志也可以帮助我们分析问题，所以，我
们可以更具实际情况决定是否开启查询日志，如果需要可以手动开启。
查询日志相关参数
MariaDB [(none)]> show variables where variable_name like "%general_log%" or variable_name = "log_output"; +------------------+---------------------+ | Variable_name | Value | +------------------+---------------------+ | general_log | OFF | | general_log_file | DESKTOP-A3DGD26.log | | log_output | FILE | +------------------+---------------------+ 3 rows in set (0.001 sec)
general_log：表示查询日志是否开启，ON表示开启，OFF表示未开启，默认未OFF
log_output：表示当查询日志开启以后，以哪种方式存放。FILE表示存放于文件中，TABLE表示存放于表mysql.general_log中(慢查询存放于表mysql.slow_log)，FILE,TABLE表示同时存放于文件和表中
，NONE表示不记录日志。log_output不仅控制查询日志，还控制慢查询日志。
general_log_file：表示查询日志存放于文件的路径
FILE：
D:\application\MariaDB 10.4\bin\mysqld.exe, Version: 10.4.7-MariaDB (mariadb.org binary distribution). started with:
TCP Port: 3306, Named Pipe: MySQL
Time Id Command Argument
190905 21:51:24 13 Connect root@localhost as anonymous on
13 Query select @@version_comment limit 1
190905 21:53:09 13 Query create database testdata
190905 21:53:18 13 Query SELECT DATABASE()
13 Init DB testdata
190905 21:53:47 13 Query create table book(namechar(20),author char(20))
190905 21:54:11 13 Query create table book(name char(20),author char(20))
190905 21:55:06 13 Query insert into book values('python','aaa')
190905 21:55:18 13 Query insert into book values('java','bbb')
190905 21:55:37 13 Query select * from book
TABLE：
MariaDB [mysql]> select * from general_log;
+----------------------------+------------------------------+-----------+-----------+--------------+-----------------------------------------------------------------------------------------+
| event_time | user_host | thread_id | server_id | command_type | argument |
+----------------------------+------------------------------+-----------+-----------+--------------+-----------------------------------------------------------------------------------------+
| 2019-09-05 21:51:24.424262 | [root] @ localhost [::1] | 13 | 1 | Connect | root@localhost as anonymous on |
| 2019-09-05 21:51:24.425389 | root[root] @ localhost [::1] | 13 | 1 | Query | select @@version_comment limit 1 |
| 2019-09-05 21:53:09.520124 | root[root] @ localhost [::1] | 13 | 1 | Query | create database testdata |
| 2019-09-05 21:53:18.755448 | root[root] @ localhost [::1] | 13 | 1 | Query | SELECT DATABASE() |
| 2019-09-05 21:53:18.755778 | root[root] @ localhost [::1] | 13 | 1 | Init DB | testdata |
| 2019-09-05 21:53:47.279001 | root[root] @ localhost [::1] | 13 | 1 | Query | create table book(namechar(20),author char(20)) |
| 2019-09-05 21:54:11.155792 | root[root] @ localhost [::1] | 13 | 1 | Query | create table book(name char(20),author char(20)) |
| 2019-09-05 21:55:06.938210 | root[root] @ localhost [::1] | 13 | 1 | Query | insert into book values('python','aaa') |
| 2019-09-05 21:55:18.342203 | root[root] @ localhost [::1] | 13 | 1 | Query | insert into book values('java','bbb') |
| 2019-09-05 21:55:37.666281 | root[root] @ localhost [::1] | 13 | 1 | Query | select * from book |
+----------------------------+------------------------------+-----------+-----------+--------------+-----------------------------------------------------------------------------------------+
21 rows in set (0.000 sec)
慢查询日志
某些sql语句执行完毕所花费的时间特别长，我们将这种响应比较慢的语句记录在慢查询日志中，只要超过指定时间的sql语句，都称为“慢查询”，被记录在慢查询日志中。
慢查询日志默认情况下是关闭的，默认设置下，超过10s的语句才会被记录到慢查询日志中。
慢查询日志相关参数
MariaDB [(none)]> show variables where variable_name like 'slow_query%' or variable_name='long_query_time' or variable_name='log_queries_not_using_indexes'; +-------------------------------+--------------------------+ | Variable_name | Value | +-------------------------------+--------------------------+ | log_queries_not_using_indexes | OFF | | long_query_time | 10.000000 | | slow_query_log | ON | | slow_query_log_file | DESKTOP-A3DGD26-slow.log | +-------------------------------+--------------------------+ 4 rows in set (0.001 sec)
slow_query_log：表示查询日志是否开启，ON表示开启，OFF表示未开启，默认OFF
slow_query_log_file：表示查询日志存放于文件的路径
long_query_time：表示多长时间的查询被认为"慢查询"，默认10s
log_queries_not_using_indexes：表示如果运行的sql语句没有使用到索引，也被记录到慢查询日志，OFF表示不记录，ON表示记录，默认OFF
FILE：
D:\application\MariaDB 10.4\bin\mysqld.exe, Version: 10.4.7-MariaDB (mariadb.org binary distribution). started with: TCP Port: 3306, Named Pipe: MySQL Time Id Command Argument # Time: 190906 3:26:04 # User@Host: root[root] @ localhost [::1] # Thread_id: 18 Schema: QC_hit: No # Query_time: 11.001576 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 # Rows_affected: 0 Bytes_sent: 64 SET timestamp=1567711564; select sleep(11); # Time: 190906 3:26:58 # User@Host: root[root] @ localhost [::1] # Thread_id: 18 Schema: QC_hit: No # Query_time: 12.000767 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 # Rows_affected: 0 Bytes_sent: 64 SET timestamp=1567711618; select sleep(12);
TABLE：
MariaDB [(none)]> select * from mysql.slow_log; +----------------------------+------------------------------+-----------------+-----------------+-----------+---------------+----+----------------+-----------+-----------+------------------+-----------+ | start_time | user_host | query_time | lock_time | rows_sent | rows_examined | db | last_insert_id | insert_id | server_id | sql_text | thread_id | +----------------------------+------------------------------+-----------------+-----------------+-----------+---------------+----+----------------+-----------+-----------+------------------+-----------+ | 2019-09-06 03:26:04.673659 | root[root] @ localhost [::1] | 00:00:11.001576 | 00:00:00.000000 | 1 | 0 | | 0 | 0 | 1 | select sleep(11) | 18 | | 2019-09-06 03:26:58.246917 | root[root] @ localhost [::1] | 00:00:12.000767 | 00:00:00.000000 | 1 | 0 | | 0 | 0 | 1 | select sleep(12) | 18 | +----------------------------+------------------------------+-----------------+-----------------+-----------+---------------+----+----------------+-----------+-----------+------------------+-----------+ 2 rows in set (0.000 sec)
二进制日志
二进制日志是一个二进制文件，记录了对MySQL数据库执行更改的所有操作，并且记录了语句发生时间、执行时长、
操作数据等其他额外信息，但是他不记录SELECT、SHOW等那些不改变数据库的SQL语句。二进制日志主要用于数据
库恢复和主从复制，以及审计操作。
二进制日志相关参数
MariaDB [(none)]> show variables where variable_name="log_bin" or variable_name="log_bin_basename" or variable_name="max_binlog_size" or variable_name="log_bin_index" or variable_name="binlog_format" or variable_name="sql_log_bin" or variable_name="sync_binlog"; +------------------+------------+ | Variable_name | Value | +------------------+------------+ | binlog_format | MIXED | | log_bin | OFF | | log_bin_basename | | | log_bin_index | | | max_binlog_size | 1073741824 | | sql_log_bin | ON | | sync_binlog | 0 | +------------------+------------+ 7 rows in set (0.001 sec)
log_bin：表示二进制日志是否开启，ON表示开启，OFF表示未开启，默认OFF
log_bin_basename：二进制日志文件前缀名，二进制日志就记录在该文件中
max_binlog_size：二进制日志文件的最大大小，超过此大小，二进制文件会自动滚动
log_bin_index：二进制日志文件索引文件名，用于记录所有的二进制文件
binlog_format：决定了二进制日志的记录方式，STATEMENT以语句的形式记录，ROW以数据修改的形式记录，MIXED以语句和数据修改混合形式记录
sql_log_bin：决定是否对二进制日志进行日志记录，ON表示执行记录，OFF表示不执行记录，默认OFF，这个是会话级别变量可以通SET sql_log_bin = {0|1}来改变该变量值
sync_binlog：决定二进制日志写入磁盘时机，如果sync_binlog为0，操作系统来决定什么时候写入磁盘，如果sync_binlog为N（N=1,2,3..），则每N次事务提交后，都立即将内存中的二进制日志写入磁盘，如何选择取决于安全性与性能的权衡
二进制日志的三种记录方式
STATEMENT：记录对数据库做出修改的语句，比如，update A set test='test'，如果使用statement模式，那么这条update语句将被记录到二进制日志中，使用statement模式时，优点是binlog日志量少，IO压力小，性能高，缺点是为了尽可能一致的还原操作，除了记录语句本身外，可能还需要记录一些相关信息，而且，在使用一些特定函数时，并不能保证恢复操作与记录完全一致
ROW：记录对数据库做出的修改的语句所影响到的数据行以及这些行的修改，比如，update A set test='test'，如果使用row模式，那么这条update所影响到的行所对应的修改，将会记录在binlog中，使用row模式时，优点是能完还原和复制被日志记录时的操作，缺点是日志量较大，IO压力比较大，性能消耗比较大
MIXED：混合上述两种模式，一般使用statement方式进行记录，如果遇到一些特殊函数使用row方式进行记录，这种记录方式称为mixed
二进制日志进行数据库恢复
修改my.cnf
[mysqld]
log_bin=bin_log_file
binlog_format=row
sync_binlog=1
server_id=7
重启mysql服务后，查看是否生效
+------------------+-----------------------------------------------------+ | Variable_name | Value | +------------------+-----------------------------------------------------+ | binlog_format | ROW | | log_bin | ON | | log_bin_basename | D:\application\MariaDB 10.4\data\bin_log_file | | log_bin_index | D:\application\MariaDB 10.4\data\bin_log_file.index | | max_binlog_size | 1073741824 | | sql_log_bin | ON | | sync_binlog | 1 | +------------------+-----------------------------------------------------+ 7 rows in set (0.001 sec)
生成的二进制日志文件和二进制日志索引文件
├─data │ ├─bin_log_file.index │ ├─bin_log_file.000001
二进制日志相关命令
MariaDB [(none)]> show binary logs; +---------------------+-----------+ | Log_name | File_size | +---------------------+-----------+ | bin_log_file.000001 | 331 | +---------------------+-----------+ 1 row in set (0.000 sec) MariaDB [(none)]> show master status; +---------------------+----------+--------------+------------------+ | File | Position | Binlog_Do_DB | Binlog_Ignore_DB | +---------------------+----------+--------------+------------------+ | bin_log_file.000001 | 331 | | | +---------------------+----------+--------------+------------------+ 1 row in set (0.000 sec) MariaDB [(none)]> show binlog events in "bin_log_file.000001"; +---------------------+-----+-------------------+-----------+-------------+-----------------------------------------------+ | Log_name | Pos | Event_type | Server_id | End_log_pos | Info | +---------------------+-----+-------------------+-----------+-------------+-----------------------------------------------+ | bin_log_file.000001 | 4 | Format_desc | 7 | 256 | Server ver: 10.4.7-MariaDB-log, Binlog ver: 4 | | bin_log_file.000001 | 256 | Gtid_list | 7 | 285 | [] | | bin_log_file.000001 | 285 | Binlog_checkpoint | 7 | 331 | bin_log_file.000001 | +---------------------+-----+-------------------+-----------+-------------+-----------------------------------------------+ 3 rows in set (0.000 sec)
新增数据，在模拟数据被误删除
创建数据库->创建表->表插入数据->表删除数据->删除表->删除数据库
create database zz; use zz; create table zz_table(id int); insert into zz_table values(1); insert into zz_table values(2); insert into zz_table values(3); insert into zz_table values(4); insert into zz_table values(5); delete from zz_table where id=4; drop table zz_table; drop database zz;
我现在需要根据二进制日志恢复到删除表之前的状态
MariaDB [(none)]> show binlog events in "bin_log_file.000001"; +---------------------+------+-------------------+-----------+-------------+-----------------------------------------------------------+ | Log_name | Pos | Event_type | Server_id | End_log_pos | Info | +---------------------+------+-------------------+-----------+-------------+-----------------------------------------------------------+ | bin_log_file.000001 | 4 | Format_desc | 7 | 256 | Server ver: 10.4.7-MariaDB-log, Binlog ver: 4 | | bin_log_file.000001 | 256 | Gtid_list | 7 | 285 | [] | | bin_log_file.000001 | 285 | Binlog_checkpoint | 7 | 331 | bin_log_file.000001 | | bin_log_file.000001 | 331 | Gtid | 7 | 373 | GTID 0-7-1 | | bin_log_file.000001 | 373 | Query | 7 | 456 | create database zz | | bin_log_file.000001 | 456 | Gtid | 7 | 498 | GTID 0-7-2 | | bin_log_file.000001 | 498 | Query | 7 | 592 | use `zz`; create table zz_table(id int) | | bin_log_file.000001 | 592 | Gtid | 7 | 634 | BEGIN GTID 0-7-3 | | bin_log_file.000001 | 634 | Annotate_rows | 7 | 687 | insert into zz_table values(1) | | bin_log_file.000001 | 687 | Table_map | 7 | 736 | table_id: 18 (zz.zz_table) | | bin_log_file.000001 | 736 | Write_rows_v1 | 7 | 774 | table_id: 18 flags: STMT_END_F | | bin_log_file.000001 | 774 | Xid | 7 | 805 | COMMIT /* xid=13 */ | | bin_log_file.000001 | 805 | Gtid | 7 | 847 | BEGIN GTID 0-7-4 | | bin_log_file.000001 | 847 | Annotate_rows | 7 | 900 | insert into zz_table values(2) | | bin_log_file.000001 | 900 | Table_map | 7 | 949 | table_id: 18 (zz.zz_table) | | bin_log_file.000001 | 949 | Write_rows_v1 | 7 | 987 | table_id: 18 flags: STMT_END_F | | bin_log_file.000001 | 987 | Xid | 7 | 1018 | COMMIT /* xid=15 */ | | bin_log_file.000001 | 1018 | Gtid | 7 | 1060 | BEGIN GTID 0-7-5 | | bin_log_file.000001 | 1060 | Annotate_rows | 7 | 1113 | insert into zz_table values(3) | | bin_log_file.000001 | 1113 | Table_map | 7 | 1162 | table_id: 18 (zz.zz_table) | | bin_log_file.000001 | 1162 | Write_rows_v1 | 7 | 1200 | table_id: 18 flags: STMT_END_F | | bin_log_file.000001 | 1200 | Xid | 7 | 1231 | COMMIT /* xid=17 */ | | bin_log_file.000001 | 1231 | Gtid | 7 | 1273 | BEGIN GTID 0-7-6 | | bin_log_file.000001 | 1273 | Annotate_rows | 7 | 1326 | insert into zz_table values(4) | | bin_log_file.000001 | 1326 | Table_map | 7 | 1375 | table_id: 18 (zz.zz_table) | | bin_log_file.000001 | 1375 | Write_rows_v1 | 7 | 1413 | table_id: 18 flags: STMT_END_F | | bin_log_file.000001 | 1413 | Xid | 7 | 1444 | COMMIT /* xid=19 */ | | bin_log_file.000001 | 1444 | Gtid | 7 | 1486 | BEGIN GTID 0-7-7 | | bin_log_file.000001 | 1486 | Annotate_rows | 7 | 1539 | insert into zz_table values(5) | | bin_log_file.000001 | 1539 | Table_map | 7 | 1588 | table_id: 18 (zz.zz_table) | | bin_log_file.000001 | 1588 | Write_rows_v1 | 7 | 1626 | table_id: 18 flags: STMT_END_F | | bin_log_file.000001 | 1626 | Xid | 7 | 1657 | COMMIT /* xid=21 */ | | bin_log_file.000001 | 1657 | Gtid | 7 | 1699 | BEGIN GTID 0-7-8 | | bin_log_file.000001 | 1699 | Annotate_rows | 7 | 1753 | delete from zz_table where id=4 | | bin_log_file.000001 | 1753 | Table_map | 7 | 1802 | table_id: 18 (zz.zz_table) | | bin_log_file.000001 | 1802 | Delete_rows_v1 | 7 | 1840 | table_id: 18 flags: STMT_END_F | | bin_log_file.000001 | 1840 | Xid | 7 | 1871 | COMMIT /* xid=23 */ | | bin_log_file.000001 | 1871 | Gtid | 7 | 1913 | GTID 0-7-9 | | bin_log_file.000001 | 1913 | Query | 7 | 2025 | use `zz`; DROP TABLE `zz_table` /* generated by server */ | | bin_log_file.000001 | 2025 | Gtid | 7 | 2067 | GTID 0-7-10 | | bin_log_file.000001 | 2067 | Query | 7 | 2148 | drop database zz | +---------------------+------+-------------------+-----------+-------------+-----------------------------------------------------------+ 41 rows in set (0.000 sec)
在文件系统中也可以通过如下命令查看
D:\application\MariaDB 10.4\data>mysqlbinlog bin_log_file.000001
根据上述日志可以发现，pos=373，end_log_pod'fdfs=1871即为要恢复的类容，截取二进制日志，放入自定义文件
mysqlbinlog --start-position=373 --stop-position=1871 bin_log_file.000001 > recover_file.sql
执行数据恢复
#临时关闭binlog set sql_log_bin=0; #执行sql文件 source recover_file.sql #开启binlog set sql_log_bin=1;
查看恢复结果
MariaDB [zz]> show tables; +--------------+ | Tables_in_zz | +--------------+ | zz_table | +--------------+ 1 row in set (0.000 sec) MariaDB [zz]> select * from zz_table; +------+ | id | +------+ | 1 | | 2 | | 3 | | 5 | +------+ 4 rows in set (0.000 sec)
