MySQL日志文件总结

MySQL日志文件总结

leo 2464 2021-05-17

MySQL日志文件

MySQL 服务器会产生很多日志，这些日志有些有助于分析问题，有些用于主从复制、崩溃恢复。有些日志仅特定存储引擎才有。MySQL 服务器产生的日志有一下几种：

错误日志（error log）

该日志记录了 MySQL 服务器的启动和关闭，以及发生错误时的相关异常信息。

如果没做特殊配置，该日志默认是在控制台输出的，可以通过修改配置文件的形式启用。

如：修改 MySQL 配置文件

[mysqld]
server-id=1
log_error=mysql_errlog.err

通过 log_error 来指定错误日志输出路径。

查看错误日志，内容如下：

2021-05-14T07:45:14.800556Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.23) starting as process 1
2021-05-14T07:45:14.920114Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2021-05-14T07:45:16.060623Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2021-05-14T07:45:16.417198Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060, socket: /var/run/mysqld/mysqlx.sock
2021-05-14T07:45:16.836572Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2021-05-14T07:45:16.836738Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2021-05-14T07:45:16.911281Z 0 [Warning] [MY-011810] [Server] Insecure configuration for --pid-file: Location '/var/run/mysqld' in the path is accessible to all OS users. Consider choosing a different directory.
2021-05-14T07:45:16.995562Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.23'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server - GPL.
2021-05-14T07:48:31.330160Z 8 [Warning] [MY-010055] [Server] IP address '172.21.0.1' could not be resolved: Name or service not known
mbind: Operation not permitted
mbind: Operation not permitted

普通查询日志（general query log）

该日志记录的内容包括：客户端连接、从客户端接收的 SQL 语句以及其他杂项事件。

#查看普通查询日志是否开启，默认关闭 OFF
show variables like '%general_log';
# ==== general_log	OFF
#查看普通查询日志文件路径
show variables like '%general_log_file';
# === general_log_file	/var/lib/mysql/f4b5d6aee6c1.log

可以通过以下语句开启普通查询日志（生产环境一般不开启）：

set global general_log = 'ON';

查看普通查询日志，内容如下：

root@ubuntu:/usr/local/docker/mysql/data$ cat f4b5d6aee6c1.log #一般是文件名是[hostname].log，我这里是容器
/usr/sbin/mysqld, Version: 8.0.23 (MySQL Community Server - GPL). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
2021-05-14T07:22:17.239062Z         9 Query     SHOW STATUS
2021-05-14T07:22:17.252241Z         9 Query     SELECT QUERY_ID, SUM(DURATION) AS SUM_DURATION FROM INFORMATION_SCHEMA.PROFILING GROUP BY QUERY_ID
2021-05-14T07:22:17.261003Z         9 Query     SELECT STATE AS `Status`, ROUND(SUM(DURATION),7) AS `Duration`, CONCAT(ROUND(SUM(DURATION)/0.001199*100,3), '') AS `Percentage` FROM INFORMATION_SCHEMA.PROFILING WHERE QUERY_ID=2 GROUP BY SEQ, STATE ORDER BY SEQ
2021-05-14T07:22:21.192739Z         8 Query     SET PROFILING = 1
2021-05-14T07:22:21.197044Z         8 Query     SHOW STATUS
2021-05-14T07:22:21.218220Z         8 Query     SHOW STATUS
2021-05-14T07:22:21.230923Z         8 Query     show variables like '%log_output'
2021-05-14T07:22:21.258249Z         8 Query     show variables like '%general_log'
2021-05-14T07:22:21.262792Z         8 Query     show variables like '%general_log_file'
2021-05-14T07:22:21.267999Z         8 Query     show variables like '%innodb_log_group_home_dir'
2021-05-14T07:22:21.272317Z         8 Query     show variables like '%slow_query_log'
2021-05-14T07:22:21.277328Z         8 Query     show variables like '%slow_query_log_file'
2021-05-14T07:22:21.281789Z         8 Query     SHOW STATUS
2021-05-14T07:22:21.293499Z         8 Query     SELECT QUERY_ID, SUM(DURATION) AS SUM_DURATION FROM INFORMATION_SCHEMA.PROFILING GROUP BY QUERY_ID
2021-05-14T07:22:21.297526Z         8 Query     SELECT STATE AS `Status`, ROUND(SUM(DURATION),7) AS `Duration`, CONCAT(ROUND(SUM(DURATION)/0.001819*100,3), '') AS `Percentage` FROM INFORMATION_SCHEMA.PROFILING WHERE QUERY_ID=89 GROUP BY SEQ, STATE ORDER BY SEQ

慢查询日志（slow query log）

该日志记录那些需要花费很长时间（默认10s， 也可以通过系统变量 long_query_time 指定）的查询。

#查看慢查询日志是否开启，默认关闭 OFF
show variables like '%slow_query_log';
# ==== slow_query_log	OFF
#查看慢查询日志文件路径
show variables like '%slow_query_log_file';
# === slow_query_log_file	/var/lib/mysql/f4b5d6aee6c1-slow.log

可以通过以下语句开启慢查询日志：

set global slow_query_log = 'ON';

查看慢查询日志，内容如下：

root@ubuntu:/usr/local/docker/mysql/data# cat f4b5d6aee6c1-slow.log
/usr/sbin/mysqld, Version: 8.0.23 (MySQL Community Server - GPL). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
# Time: 2021-05-14T08:13:18.915396Z
# User@Host: root[root] @  [172.21.0.1]  Id:     8
# Query_time: 14.563829  Lock_time: 0.000378 Rows_sent: 1041828  Rows_examined: 306
use learn;
SET timestamp=1620979984;
select m1.*, m2.*, m3.* from member as m1 inner join member as m2 inner join member as m3
where m1.interests like '%a%' or m2.interests like '%b%';

可以看到上面包含一条慢查询 SQL。工作中对于慢查询一般都要进行优化/重写。

二进制日志（binlog）

MySQL 使用 binlog 来记录各种数据修改事件（如：insert、update、delete。DDL 也会记录）。用途包括：数据备份和恢复，主从复制。该日志不是文本格式，而是二进制格式。可以通过 MySQL 提供的 mysqlbinlog工具查看二进制日志的内容。

查看 binlog 日志，内容如下：

root@ubuntu:/var/lib/mysql# mysqlbinlog binlog.000004
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#210513  9:55:15 server id 1  end_log_pos 125 CRC32 0x0c56e7d0  Start: binlog v 4, server v 8.0.23 created 210513  9:55:15 at startup
ROLLBACK/*!*/;
BINLOG '
A4ecYA8BAAAAeQAAAH0AAAAAAAQAOC4wLjIzAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAADh5xgEwANAAgAAAAABAAEAAAAYQAEGggAAAAICAgCAAAACgoKKioAEjQA
CigB0OdWDA==
'/*!*/;
# at 125
#210513  9:55:16 server id 1  end_log_pos 156 CRC32 0x9979a33e  Previous-GTIDs
# [empty]
# at 156
#210513 15:12:23 server id 1  end_log_pos 235 CRC32 0x02e4c867  Anonymous_GTID  last_committed=0        sequence_number=1       rbr_only=no     original_committed_timestamp=1620889944271107   immediate_commit_timestamp=1620889944271107      transaction_length=626
# original_commit_timestamp=1620889944271107 (2021-05-13 15:12:24.271107 CST)
# immediate_commit_timestamp=1620889944271107 (2021-05-13 15:12:24.271107 CST)
/*!80001 SET @@session.original_commit_timestamp=1620889944271107*//*!*/;
/*!80014 SET @@session.original_server_version=80023*//*!*/;
/*!80014 SET @@session.immediate_server_version=80023*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 235
#210513 15:12:23 server id 1  end_log_pos 782 CRC32 0x07c34b3e  Query   thread_id=8     exec_time=1     error_code=0    Xid = 47
use `learn`/*!*/;
SET TIMESTAMP=1620889943/*!*/;
SET @@session.pseudo_thread_id=8/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1168113696/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
/*!80013 SET @@session.sql_require_primary_key=0*//*!*/;
CREATE TABLE member
(
  member_id  INT UNSIGNED NOT NULL AUTO_INCREMENT,
  PRIMARY KEY (member_id),
  last_name  VARCHAR(20) NOT NULL,
  first_name VARCHAR(20) NOT NULL,
  suffix     VARCHAR(5) NULL,
  expiration DATE NULL,
  email      VARCHAR(100) NULL,
  street     VARCHAR(50) NULL,
  city       VARCHAR(50) NULL,
  state      VARCHAR(2) NULL,
  zip        VARCHAR(10) NULL,
  phone      VARCHAR(20) NULL,
  interests  VARCHAR(255) NULL
)
/*!*/;
# at 782

每次服务器重启或日志文件大小达到最大值，都会按顺序生成 binlog 日志文件。

binlog 格式

binlog 有三种格式：

  • ROW：每条记录的修改都会被记录。

    优点：不存在数据不一致的情况。

    缺点：一旦修改表结构( alter table) 会出现 binlog 暴涨现象。

  • STATEMENT：每执行一条导致值变化的 sql 就会记录到 binlog 中。

    优点： 仅仅记录了SQL，不会记录执行结果，减少了 binlog 日志量，节约了 IO，提高了性能

    缺点：会出现数据不一致的情况。

  • MIXED：以上两种模式混合使用，MySQL 会根据一些条件自动选择切换。

#查看binlog格式
show variables like '%binlog_format';
#我这里是mysql8，默认是ROW
# === binlog_format	ROW

中继日志（relay log）

relay log 需要和主从复制中的从服务器一起使用。主从同步流程如下图：

mysql主从同步原理图

从服务器上的 IO 线程负责上图 3，4 步。 SQL 线程负责上图第 5 步。IO 线程和 SQL 线程可以同时运行。

想要查看 relay log，必须是在从服务器上查看，所以需要事先搭建 MySQL 主从集群。

如果采用 docker-compose 搭建的话，可以参考我的这篇文章：docker-compose部署MySQL主从

进入从服务器查看 relay log，内容如下：

root@e5003398c28f:/var/lib/mysql# mysqlbinlog 4f6e5ca7e778-relay-bin.000004
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#210315  2:57:43 server id 11  end_log_pos 123 CRC32 0x55b84ccd         Start: binlog v 4, server v 5.7.33 created 210315  2:57:43
# This Format_description_event appears in a relay log and was generated by the slave thread.
# at 123
#210315  2:57:43 server id 11  end_log_pos 154 CRC32 0x3da0d148         Previous-GTIDs
# [empty]
# at 154
#700101  0:00:00 server id 1  end_log_pos 0 CRC32 0x8534fe5d    Rotate to mysql-bin.000003  pos: 5918
# at 201
#210311  6:30:22 server id 1  end_log_pos 0 CRC32 0xfd06e4bc    Start: binlog v 4, server v 5.7.33-log created 210311  6:30:22
BINLOG '
/rhJYA8BAAAAdwAAAAAAAAAAAAQANS43LjMzLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AbzkBv0=
'/*!*/;
# at 320
#210315  2:57:43 server id 11  end_log_pos 380 CRC32 0xc2bbdb78         Rotate to 4f6e5ca7e778-relay-bin.000005  pos: 4
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

日志输出方式

对于前面提到的普通日志和慢查询日志，即可以将日志输出到文件，也可以输出到日志表，也可以同时输出到文件和日志表。日志表在系统数据库mysql中已经定义好了。

#查看日志输出方式
show variables like '%log_output';
#默认是文件
#=== log_output	FILE

可以通过以下语句更改：

set global log_output = 'FILE,TABLE';

普通查询日志对应mysql系统库里的general_log表；慢查询日志对应slow_log表。

MySQL