Mysql日志概述
Mysql日志
作用
日志主要用来记录mysql实例在运行过程中发生的事件。
比如，错误日志记录着mysql中出现的错误，DBA可以根据错误来定位问题。
慢查询日志记录着mysql中查询时间过长的sql语句，从而优化sql语句。
分类
mysql中常用的日志分为5种：查询日志，错误日志，慢查询日志，事务日志，二进制日志。
查询日志
查询日志会记录用户的所有操作，包括CRUD等，如果在高并发的场景下，会导致磁盘IO过大，影响性能，所以查询日志之在默认情况下是关闭的。
使用show variables like "%general_log%";查看是否开启。
mysql> show variables like "%general_log%";
+------------------+------------------------------------------------------------+
| Variable_name | Value |
+------------------+------------------------------------------------------------+
| general_log | OFF |
| general_log_file | /software/mysql/mysql3307/data/iz2zeaf5jdjve80rjlsjgnz.log |
+------------------+------------------------------------------------------------+
2 rows in set (1.81 sec)
在查询到的log字段中，有一个general_log_file，是设置查询日志保存位置，文件名是iz2zeaf5jdjve80rjlsjgnz.log。
其实，日志的输出方式有三种：文件（file），表（table），不保存（none）。
file：输出到指定位置，如：iz2zeaf5jdjve80rjlsjgnz.log。
table：输出到mysql数据库下的general_log表。
mysql> use mysql;
Database changed
mysql> show tables;
+---------------------------+
| Tables_in_mysql |
+---------------------------+
| columns_priv |
| db |
| engine_cost |
| event |
| func |
| general_log |
| gtid_executed |
| help_category |
| help_keyword |
| help_relation |
| help_topic |
| innodb_index_stats |
| innodb_table_stats |
| ndb_binlog_index |
| plugin |
| proc |
| procs_priv |
| proxies_priv |
| server_cost |
| servers |
| slave_master_info |
| slave_relay_log_info |
| slave_worker_info |
| slow_log |
| tables_priv |
| time_zone |
| time_zone_leap_second |
| time_zone_name |
| time_zone_transition |
| time_zone_transition_type |
| user |
+---------------------------+
31 rows in set (0.18 sec)
none：开启日志功能但不保存。
错误日志
错误日志不完全是记录错误信息，它还记录着服务器启动关闭时的信息，运行事件信息等。
在mysql实例中，错误日志默认是开启的，且不能够被关闭。默认保存在mysql实例中指定的数据库目录下。
[root@iz2zeaf5jdjve80rjlsjgnz ~]# cd /software/mysql/mysql3307/data
[root@iz2zeaf5jdjve80rjlsjgnz data]# ls
amoeba ib_logfile1 iz2zeaf5jdjve80rjlsjgnz-relay-bin.000007 mysql mysql-bin.000008 mysql-bin.000016 rlxy93
auto.cnf ibtmp1 iz2zeaf5jdjve80rjlsjgnz-relay-bin.000008 mysql-bin.000001 mysql-bin.000009 mysql-bin.000017 sys
DB1 iz2zeaf5jdjve80rjlsjgnz.err iz2zeaf5jdjve80rjlsjgnz-relay-bin.000009 mysql-bin.000002 mysql-bin.000010 mysql-bin.000018
DB2 iz2zeaf5jdjve80rjlsjgnz-relay-bin.000002 iz2zeaf5jdjve80rjlsjgnz-relay-bin.000010 mysql-bin.000003 mysql-bin.000011 mysql-bin.000019
DB3 iz2zeaf5jdjve80rjlsjgnz-relay-bin.000003 iz2zeaf5jdjve80rjlsjgnz-relay-bin.000011 mysql-bin.000004 mysql-bin.000012 mysql-bin.000020
ib_buffer_pool iz2zeaf5jdjve80rjlsjgnz-relay-bin.000004 iz2zeaf5jdjve80rjlsjgnz-relay-bin.index mysql-bin.000005 mysql-bin.000013 mysql-bin.index
ibdata1 iz2zeaf5jdjve80rjlsjgnz-relay-bin.000005 lll mysql-bin.000006 mysql-bin.000014 performance_schema
ib_logfile0 iz2zeaf5jdjve80rjlsjgnz-relay-bin.000006 master.info mysql-bin.000007 mysql-bin.000015 relay-log.info
使用命令show variables like "%log_error%";
mysql> show variables like "%log_error%";
+---------------------+-------------------------------+
| Variable_name | Value |
+---------------------+-------------------------------+
| binlog_error_action | ABORT_SERVER |
| log_error | ./iz2zeaf5jdjve80rjlsjgnz.err |
| log_error_verbosity | 3 |
+---------------------+-------------------------------+
3 rows in set (0.34 sec)
目录可以通过set命令定义，也可以在my.cnf文件中配置。
[mysqld]
Log_error=dir/[filename]
其中，dir是目录，filename是错误日志的名称，如果没有指定filename，那么默认是主机名.err。
ps:错误日志内容有很多，如果出现错误，找到[ERROR]行，去相应的搜索一下具体的错误提示的解决办法。
2019-11-23T17:36:26.736821Z 0 [Warning] 'NO_ZERO_DATE', 'NO_ZERO_IN_DATE' and 'ERROR_FOR_DIVISION_BY_ZERO' sql modes should be used with strict mode. They will be merged with strict mode in a future release.
2019-11-23T17:36:26.736950Z 0 [Warning] 'NO_AUTO_CREATE_USER' sql mode was not set.
2019-11-23T17:36:26.737004Z 0 [Note] --secure-file-priv is set to NULL. Operations related to importing and exporting data are disabled
2019-11-23T17:36:26.737047Z 0 [Note] /software/mysql/mysql3309/bin/mysqld (mysqld 5.7.24-log) starting as process 12366 ...
2019-11-23T17:36:26.887293Z 0 [Note] InnoDB: PUNCH HOLE support available
2019-11-23T17:36:26.887351Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-11-23T17:36:26.887361Z 0 [Note] InnoDB: Uses event mutexes
2019-11-23T17:36:26.887368Z 0 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
2019-11-23T17:36:26.887373Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-11-23T17:36:26.887379Z 0 [Note] InnoDB: Using Linux native AIO
2019-11-23T17:36:26.887402Z 0 [Note] InnoDB: Adjusting innodb_buffer_pool_instances from 8 to 1 since innodb_buffer_pool_size is less than 1024 MiB
2019-11-23T17:36:26.889633Z 0 [Note] InnoDB: Number of pools: 1
2019-11-23T17:36:26.889872Z 0 [Note] InnoDB: Using CPU crc32 instructions
2019-11-23T17:36:26.893296Z 0 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
2019-11-23T17:36:26.930095Z 0 [Note] InnoDB: Completed initialization of buffer pool
2019-11-23T17:36:26.939130Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-11-23T17:36:26.957881Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2019-11-23T17:36:26.964463Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 2591850
2019-11-23T17:36:26.964511Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 2591859
2019-11-23T17:36:26.964522Z 0 [Note] InnoDB: Database was not shutdown normally!
2019-11-23T17:36:26.964532Z 0 [Note] InnoDB: Starting crash recovery.
2019-11-23T17:36:27.104373Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2019-11-23T17:36:27.104396Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-11-23T17:36:27.104506Z 0 [Note] InnoDB: Setting file '/software/mysql/mysql3309/data/ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-11-23T17:36:27.124417Z 0 [Note] InnoDB: File '/software/mysql/mysql3309/data/ibtmp1' size is now 12 MB.
2019-11-23T17:36:27.125457Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2019-11-23T17:36:27.125472Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2019-11-23T17:36:27.125768Z 0 [Note] InnoDB: Waiting for purge to start
2019-11-23T17:36:27.175981Z 0 [Note] InnoDB: 5.7.24 started; log sequence number 2591859
2019-11-23T17:36:27.176414Z 0 [Note] Plugin 'FEDERATED' is disabled.
2019-11-23T17:36:27.176886Z 0 [Note] InnoDB: Loading buffer pool(s) from /software/mysql/mysql3309/data/ib_buffer_pool
2019-11-23T17:36:27.187273Z 0 [Note] InnoDB: Buffer pool(s) load completed at 191124 1:36:27
2019-11-23T17:36:27.191461Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2019-11-23T17:36:27.191488Z 0 [Note] Server hostname (bind-address): '*'; port: 3309
2019-11-23T17:36:27.191559Z 0 [Note] IPv6 is available.
2019-11-23T17:36:27.191574Z 0 [Note] - '::' resolves to '::';
2019-11-23T17:36:27.191665Z 0 [Note] Server socket created on IP: '::'.
2019-11-23T17:36:27.191741Z 0 [ERROR] Another process with pid 11149 is using unix socket file.
2019-11-23T17:36:27.191746Z 0 [ERROR] Unable to setup unix socket lock file.
2019-11-23T17:36:27.191764Z 0 [ERROR] Aborting
如何删除错误日志？
在mysql5.5.7版本之前，可以使用mysqladmin命令来创建一个新的错误日志，具体语法如下：
mysqladmin –u root –pflush-logs
也可以登录数据库，然后使用FLUSHLOGS命令来创建一个新的错误日志。
在mysql5.5.7之后，只能通过对错误日志文件进行操作。
1、删除错误日志。
2、重命名错误日志。
慢查询日志
慢查询日志是记录查询超过指定时间的查询语句。通过慢查询日志分析，可以知道哪些查询语句效率较低。
使用show variables like "%slow_query_log%";语句来查看是否开启。
mysql> show variables like "%slow_query_log%";
+---------------------+-----------------------------------------------------------------+
| Variable_name | Value |
+---------------------+-----------------------------------------------------------------+
| slow_query_log | OFF |
| slow_query_log_file | /software/mysql/mysql3310/data/iz2zeaf5jdjve80rjlsjgnz-slow.log |
+---------------------+-----------------------------------------------------------------+
2 rows in set (0.26 sec)
slow_query_log的值是OFF，可以通过set命令手动开启。
mysql> set global slow_query_log = on;
Query OK, 0 rows affected (0.16 sec)
mysql> show variables like "%slow_query_log%";
+---------------------+-----------------------------------------------------------------+
| Variable_name | Value |
+---------------------+-----------------------------------------------------------------+
| slow_query_log | ON |
| slow_query_log_file | /software/mysql/mysql3310/data/iz2zeaf5jdjve80rjlsjgnz-slow.log |
+---------------------+-----------------------------------------------------------------+
2 rows in set (0.07 sec)
前面提到，慢查询日志是记录超过指定查询时间的查询语句，那么这个时间是多少？
使用show variables like "%long_query_time%";即可查看。
mysql> show variables like "%long_query_time%";
+-----------------+-----------+
| Variable_name | Value |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.07 sec)
默认是10秒。
尝试使用一条查询事件超过10秒的语句：
mysql> select sleep(10);
+-----------+
| sleep(10) |
+-----------+
| 0 |
+-----------+
1 row in set (10.08 sec)
前面有一个slow_query_log_file值是data/iz2zeaf5jdjve80rjlsjgnz-slow.log，查看一下这个日志。
/software/mysql/mysql3310/bin/mysqld, Version: 5.7.24-log (MySQL Community Server (GPL)). started with:
Tcp port: 3310 Unix socket: /tmp/mysql.sock
Time Id Command Argument
# Time: 2019-11-28T10:46:17.752905Z
# User@Host: root[root] @ [218.194.188.165] Id: 235
# Query_time: 10.003016 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1574937977;
select sleep(10);
最后一行记录着刚才的select语句。
修改long_query_time的值再使用其他的sql语句查询：
mysql> set global long_query_time = 0.001;
Query OK, 0 rows affected (0.04 sec)
mysql> exit
#注意：这里要重新开启mysql会话才会生效。
mysql> use DB1;
Database changed
mysql> select * from ADMIN;
+---------+-------------------------+------------+-----+------+
| ID | USER_ID | TRAVELDATE | FEE | DAYS |
+---------+-------------------------+------------+-----+------+
| 1 | iz2zeaf5jdjve80rjlsjgnz | 2016-01-01 | 100 | 10 |
| 2 | iz2zeaf5jdjve80rjlsjgnz | 2019-11-26 | 100 | 10 |
+---------+-------------------------+------------+-----+------+
2 rows in set (0.39 sec)
再查看iz2zeaf5jdjve80rjlsjgnz-slow.log日志：
/software/mysql/mysql3310/bin/mysqld, Version: 5.7.24-log (MySQL Community Server (GPL)). started with:
Tcp port: 3310 Unix socket: /tmp/mysql.sock
Time Id Command Argument
# Time: 2019-11-28T10:46:17.752905Z
# User@Host: root[root] @ [218.194.188.165] Id: 235
# Query_time: 10.003016 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1574937977;
select sleep(10);
# Time: 2019-11-28T10:51:44.124890Z
# User@Host: root[root] @ [218.194.188.165] Id: 236
# Query_time: 0.006033 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
SET timestamp=1574938304;
SET NAMES utf8mb4;
# Time: 2019-11-28T10:51:44.175882Z
# User@Host: root[root] @ [218.194.188.165] Id: 236
# Query_time: 0.006011 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
SET timestamp=1574938304;
KILL 235;
# Time: 2019-11-28T10:52:00.059604Z
# User@Host: root[root] @ [218.194.188.165] Id: 237
# Query_time: 0.012702 Lock_time: 0.011107 Rows_sent: 1 Rows_examined: 1026
use DB1;
SET timestamp=1574938320;
show variables like "%long_query_time%";
没有记录。
这是因为select * from ADMIN;这一条语句没有使用索引，需要将 记录没有使用索引的语句 开启。
mysql> show variables like 'log_queries_not_using_indexes';
+-------------------------------+-------+
| Variable_name | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | OFF |
+-------------------------------+-------+
1 row in set (0.17 sec)
mysql> set global log_queries_not_using_indexes=1;
Query OK, 0 rows affected (0.08 sec)
mysql> show variables like 'log_queries_not_using_indexes';
+-------------------------------+-------+
| Variable_name | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | ON |
+-------------------------------+-------+
1 row in set (0.21 sec)
再次查询
mysql> use DB1;
Database changed
mysql> select * from ADMIN;
+---------+-------------------------+------------+-----+------+
| ID | USER_ID | TRAVELDATE | FEE | DAYS |
+---------+-------------------------+------------+-----+------+
| 1 | iz2zeaf5jdjve80rjlsjgnz | 2016-01-01 | 100 | 10 |
| 2 | iz2zeaf5jdjve80rjlsjgnz | 2019-11-26 | 100 | 10 |
+---------+-------------------------+------------+-----+------+
2 rows in set (0.39 sec)
查看日志
/software/mysql/mysql3310/bin/mysqld, Version: 5.7.24-log (MySQL Community Server (GPL)). started with:
Tcp port: 3310 Unix socket: /tmp/mysql.sock
Time Id Command Argument
# Time: 2019-11-28T11:18:07.059220Z
# User@Host: root[root] @ [218.194.188.165] Id: 6
# Query_time: 0.000386 Lock_time: 0.000105 Rows_sent: 166 Rows_examined: 166
use DB1;
SET timestamp=1574939887;
select * from ADMIN;
就成功记录下来了。
使用show global status like '%slow_queries%';可以查看慢查询日志里面有多少记录。
mysql> show global status like '%slow_queries%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Slow_queries | 1 |
+---------------+-------+
1 row in set (0.43 sec)
ps:最好开启slow_query_log和log_queries_not_using_indexes这两个。
事务日志
事务日志是用来记录mysql中事务的操作，使用事务日志，能够提高事务的效率。
mysql在进行事务操作的时候，先将数据从硬盘读取，在进行操作时将操作写入事务日志，而不是将数据直接写到硬盘，再在后台将操作记录执行。
使用show variables like "%log%";来查看事务日志状态。
mysql> show variables like "%log%";
+--------------------------------------------+------------------------------------------------------------------------+
| Variable_name | Value |
+--------------------------------------------+------------------------------------------------------------------------+
| innodb_api_enable_binlog | OFF |
| innodb_flush_log_at_timeout | 1 |
| innodb_flush_log_at_trx_commit | 0 |
| innodb_locks_unsafe_for_binlog | OFF |
| innodb_log_buffer_size | 16777216 |
| innodb_log_checksums | ON |
| innodb_log_compressed_pages | ON |
| innodb_log_file_size | 134217728 |
| innodb_log_files_in_group | 2 |
| innodb_log_group_home_dir | ./ |
| innodb_log_write_ahead_size | 8192 |
| innodb_max_undo_log_size | 1073741824 |
| innodb_online_alter_log_max_size | 134217728 |
| innodb_undo_log_truncate | OFF |
| innodb_undo_logs | 128 |
+--------------------------------------------+------------------------------------------------------------------------+
二进制日志
二进制日志主要用来记录数据修改或者有可能引起数据修改的语句，还记录着语句的时间，执行时间，操作的什么数据。
使用show global variables like "%log_bin%";查看二进制日志开启状态。
mysql> show global variables like "%log_bin%";
+---------------------------------+------------------------------------------------+
| Variable_name | Value |
+---------------------------------+------------------------------------------------+
| log_bin | ON |
| log_bin_basename | /software/mysql/mysql3310/data/mysql-bin |
| log_bin_index | /software/mysql/mysql3310/data/mysql-bin.index |
| log_bin_trust_function_creators | ON |
| log_bin_use_v1_row_events | OFF |
+---------------------------------+------------------------------------------------+
5 rows in set (0.37 sec)
log_bin的值为ON表示已经开启。
使用show binlog events in "二进制日志文件名";查看二进制日志。
mysql> show binlog events in 'mysql-bin.000001';
+------------------+------+----------------+-----------+-------------+-----------------------------------------------------------------------------------------------------------------------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+------------------+------+----------------+-----------+-------------+-----------------------------------------------------------------------------------------------------------------------------------------------+
| mysql-bin.000001 | 4 | Format_desc | 4 | 123 | Server ver: 5.7.24-log, Binlog ver: 4 |
| mysql-bin.000001 | 123 | Previous_gtids | 4 | 154 | |
| mysql-bin.000001 | 154 | Anonymous_Gtid | 4 | 219 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |
| mysql-bin.000001 | 219 | Query | 4 | 398 | ALTER USER 'root'@'localhost' IDENTIFIED WITH 'mysql_native_password' AS '*81F5E21E35407D884A6CD4A731AEBFB6AF209E1B' |
| mysql-bin.000001 | 398 | Anonymous_Gtid | 4 | 463 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |
| mysql-bin.000001 | 463 | Query | 4 | 536 | BEGIN |
| mysql-bin.000001 | 536 | Table_map | 4 | 708 | table_id: 4 (mysql.user) |
| mysql-bin.000001 | 708 | Update_rows | 4 | 1034 | table_id: 4 flags: STMT_END_F |
| mysql-bin.000001 | 1034 | Query | 4 | 1108 | COMMIT |
| mysql-bin.000001 | 1108 | Anonymous_Gtid | 4 | 1173 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |
| mysql-bin.000001 | 1173 | Query | 4 | 1265 | use `mysql`; FLUSH PRIVILEGES |
| mysql-bin.000001 | 1265 | Anonymous_Gtid | 4 | 1330 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |
| mysql-bin.000001 | 1330 | Query | 4 | 1550 | use `mysql`; GRANT ALL PRIVILEGES ON *.* TO 'root'@'%' IDENTIFIED WITH 'mysql_native_password' AS '*81F5E21E35407D884A6CD4A731AEBFB6AF209E1B' |
| mysql-bin.000001 | 1550 | Anonymous_Gtid | 4 | 1615 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |
| mysql-bin.000001 | 1615 | Query | 4 | 1707 | use `mysql`; flush privileges |
+------------------+------+----------------+-----------+-------------+-----------------------------------------------------------------------------------------------------------------------------------------------+
15 rows in set (0.19 sec)
