印刻数据库

外观

MySQL 常见日志条目 ​

错误日志 (Error Log) ​

1. 启动和关闭日志条目 ​

  • 正常启动

    2024-01-01T12:00:00.123456Z 0 [Note] mysqld (mysqld 8.0.36) starting as process 1234 ...
2024-01-01T12:00:00.234567Z 1 [Note] InnoDB: Using Linux native AIO
2024-01-01T12:00:00.345678Z 1 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2024-01-01T12:00:00.456789Z 1 [Note] InnoDB: Uses event mutexes
2024-01-01T12:00:00.567890Z 1 [Note] InnoDB: Compressed tables use zlib 1.2.11
2024-01-01T12:00:00.678901Z 1 [Note] InnoDB: Number of pools: 1
2024-01-01T12:00:00.789012Z 1 [Note] InnoDB: Using SSE2 crc32 instructions
2024-01-01T12:00:00.890123Z 1 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2024-01-01T12:00:01.001234Z 1 [Note] InnoDB: Completed initialization of buffer pool
2024-01-01T12:00:01.112345Z 1 [Note] InnoDB: Starting crash recovery from checkpoint LSN=123456789
2024-01-01T12:00:01.223456Z 1 [Note] InnoDB: Starting final batch to recover 123 pages from redo log.
2024-01-01T12:00:01.334567Z 1 [Note] InnoDB: Crash recovery completed.
2024-01-01T12:00:01.445678Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
2024-01-01T12:00:01.556789Z 0 [Note] IPv6 is available.
2024-01-01T12:00:01.667890Z 0 [Note]   - '::' resolves to '::';
2024-01-01T12:00:01.778901Z 0 [Note] Server socket created on IP: '::'.
2024-01-01T12:00:01.889012Z 0 [Note] mysqld: ready for connections.
Version: '8.0.36'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server - GPL.

  • 正常关闭

    2024-01-01T13:00:00.123456Z 0 [Note] Giving 1 client threads a chance to die gracefully
2024-01-01T13:00:00.234567Z 0 [Note] Shutting down slave threads
2024-01-01T13:00:00.345678Z 0 [Note] Forcefully disconnecting 1 remaining clients
2024-01-01T13:00:00.456789Z 0 [Note] Event Scheduler: Purging the queue. 0 events
2024-01-01T13:00:00.567890Z 0 [Note] Binlog end
2024-01-01T13:00:00.678901Z 1 [Note] InnoDB: FTS optimize thread exiting.
2024-01-01T13:00:00.789012Z 1 [Note] InnoDB: Starting shutdown...
2024-01-01T13:00:00.890123Z 1 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
2024-01-01T13:00:01.001234Z 1 [Note] InnoDB: Buffer pool(s) dump completed at 240101 13:00:01
2024-01-01T13:00:01.112345Z 1 [Note] InnoDB: Shutdown completed; log sequence number 1234567890
2024-01-01T13:00:01.223456Z 0 [Note] mysqld: Shutdown complete

2. 错误和警告日志条目 ​

  • 启动失败 - 端口被占用

    2024-01-01T12:00:00.123456Z 0 [ERROR] Can't start server: Bind on TCP/IP port: Address already in use
2024-01-01T12:00:00.234567Z 0 [ERROR] Do you already have another mysqld server running on port: 3306 ?
2024-01-01T12:00:00.345678Z 0 [ERROR] Aborting

  • 启动失败 - 数据目录不存在

    2024-01-01T12:00:00.123456Z 0 [ERROR] [MY-011011] [Server] Failed to find valid data directory.
2024-01-01T12:00:00.234567Z 0 [ERROR] [MY-010020] [Server] Data Dictionary initialization failed.
2024-01-01T12:00:00.345678Z 0 [ERROR] [MY-010119] [Server] Aborting

  • InnoDB 错误 - 表空间损坏

    2024-01-01T12:00:00.123456Z 1 [ERROR] [MY-012890] [InnoDB] Tablespace 'innodb_system' is corrupted.
2024-01-01T12:00:00.234567Z 1 [ERROR] [MY-012930] [InnoDB] Plugin initialization aborted with error Tablespace corruption.
2024-01-01T12:00:00.345678Z 0 [ERROR] [MY-010334] [Server] Failed to initialize DD Storage Engine
2024-01-01T12:00:00.456789Z 0 [ERROR] [MY-010020] [Server] Data Dictionary initialization failed.
2024-01-01T12:00:00.567890Z 0 [ERROR] [MY-010119] [Server] Aborting

  • 权限错误 - 无法访问文件

    2024-01-01T12:00:00.123456Z 1 [ERROR] [MY-012574] [InnoDB] The innodb_system data file 'ibdata1' must be writable
2024-01-01T12:00:00.234567Z 1 [ERROR] [MY-012576] [InnoDB] The innodb_system data file 'ibdata1' is not writable
2024-01-01T12:00:00.345678Z 1 [ERROR] [MY-012930] [InnoDB] Plugin initialization aborted with error Generic error.
2024-01-01T12:00:00.456789Z 0 [ERROR] [MY-010334] [Server] Failed to initialize DD Storage Engine

  • 内存不足警告

    2024-01-01T12:00:00.123456Z 1 [Warning] [MY-012654] [InnoDB] InnoDB: Buffer pool was not large enough to keep all index and data blocks in memory.

  • 连接数超过限制

    2024-01-01T12:00:00.123456Z 0 [Warning] [MY-010918] [Server] 'max_connections' was set to 151, but the value is invalid; setting to 1.
2024-01-01T12:00:00.234567Z 0 [Note] [MY-010139] [Server] Adjusting 'max_connections' from 151 to 2147483647.

3. 运行时错误日志条目 ​

  • 死锁错误

    2024-01-01T12:00:00.123456Z 1 [Note] [MY-012073] [InnoDB] Transaction 123456789 was deadlocked on index PRIMARY with another transaction or query, and has been rolled back. See https://dev.mysql.com/doc/refman/8.0/en/innodb-deadlocks.html for more information.

  • 表不存在错误

    2024-01-01T12:00:00.123456Z 2 [Note] [MY-010001] [Server] Can't find table `test`.`nonexistent_table` in the cache.

  • 权限拒绝错误

    2024-01-01T12:00:00.123456Z 3 [Note] [MY-010926] [Server] Access denied for user 'test'@'localhost' (using password: YES)

查询日志 (General Query Log) ​

1. 连接和断开连接日志 ​

  • 客户端连接

    2024-01-01T12:00:00.123456Z	   4 Connect	root@localhost on  using Socket

  • 客户端断开连接

    2024-01-01T12:00:00.234567Z	   4 Quit

2. 查询执行日志 ​

  • SELECT 查询

    2024-01-01T12:00:00.123456Z	   4 Query	SELECT * FROM test_table WHERE id = 1

  • INSERT 查询

    2024-01-01T12:00:00.234567Z	   4 Query	INSERT INTO test_table (name, value) VALUES ('test', 123)

  • UPDATE 查询

    2024-01-01T12:00:00.345678Z	   4 Query	UPDATE test_table SET value = 456 WHERE id = 1

  • DELETE 查询

    2024-01-01T12:00:00.456789Z	   4 Query	DELETE FROM test_table WHERE id = 1

  • DDL 语句

    2024-01-01T12:00:00.567890Z	   4 Query	CREATE TABLE new_table (id INT PRIMARY KEY AUTO_INCREMENT, name VARCHAR(50))
2024-01-01T12:00:00.678901Z	   4 Query	ALTER TABLE test_table ADD COLUMN new_column INT
2024-01-01T12:00:00.789012Z	   4 Query	DROP TABLE old_table

3. 管理命令日志 ​

  • FLUSH 命令

    2024-01-01T12:00:00.123456Z	   4 Query	FLUSH TABLES
2024-01-01T12:00:00.234567Z	   4 Query	FLUSH LOGS

  • GRANT 和 REVOKE 命令

    2024-01-01T12:00:00.345678Z	   4 Query	GRANT SELECT ON test.* TO 'user'@'localhost'
2024-01-01T12:00:00.456789Z	   4 Query	REVOKE INSERT ON test.* FROM 'user'@'localhost'

慢查询日志 (Slow Query Log) ​

1. 慢查询日志格式 ​

  • 标准慢查询日志条目

    # Time: 2024-01-01T12:00:00.123456Z
# User@Host: root[root] @ localhost []  Id:     4
# Query_time: 1.234567  Lock_time: 0.001234 Rows_sent: 100000  Rows_examined: 200000
SET timestamp=1234567890;
SELECT * FROM large_table WHERE category = 'test' ORDER BY id DESC;

  • 带执行计划的慢查询日志条目（MySQL 8.0+）

    # Time: 2024-01-01T12:00:00.123456Z
# User@Host: root[root] @ localhost []  Id:     4
# Query_time: 1.234567  Lock_time: 0.001234 Rows_sent: 100000  Rows_examined: 200000
# Full_scan: Yes  Full_join: No  Tmp_table: Yes  Tmp_table_on_disk: No
# Filesort: Yes  Filesort_on_disk: Yes  Merge_passes: 10
SET timestamp=1234567890;
SELECT * FROM large_table WHERE category = 'test' ORDER BY id DESC;

2. 常见慢查询类型 ​

  • 全表扫描

    # Time: 2024-01-01T12:00:00.123456Z
# User@Host: root[root] @ localhost []  Id:     4
# Query_time: 5.678901  Lock_time: 0.000123 Rows_sent: 1  Rows_examined: 1000000
# Full_scan: Yes
SET timestamp=1234567890;
SELECT * FROM large_table WHERE non_indexed_column = 'value';

  • 临时表使用

    # Time: 2024-01-01T12:00:00.123456Z
# User@Host: root[root] @ localhost []  Id:     4
# Query_time: 2.345678  Lock_time: 0.000456 Rows_sent: 100  Rows_examined: 50000
# Tmp_table: Yes  Tmp_table_on_disk: Yes
SET timestamp=1234567890;
SELECT COUNT(*), category FROM large_table GROUP BY category;

  • 文件排序

    # Time: 2024-01-01T12:00:00.123456Z
# User@Host: root[root] @ localhost []  Id:     4
# Query_time: 3.456789  Lock_time: 0.000789 Rows_sent: 1000  Rows_examined: 100000
# Filesort: Yes  Filesort_on_disk: Yes
SET timestamp=1234567890;
SELECT * FROM large_table ORDER BY non_indexed_column LIMIT 1000;

  • 长时间锁定

    # Time: 2024-01-01T12:00:00.123456Z
# User@Host: root[root] @ localhost []  Id:     4
# Query_time: 0.123456  Lock_time: 0.567890 Rows_sent: 100  Rows_examined: 100
SET timestamp=1234567890;
UPDATE large_table SET value = 'new' WHERE category = 'test';

二进制日志 (Binary Log) ​

1. 二进制日志文件头 ​

  • 二进制日志文件开始
    # Log name: mysql-bin.000001
# Position: 4
# Binlog Version: 4
# Server Version: 8.0.36
# Start Time: 2024-01-01T12:00:00.000000Z
# End Time: 2024-01-01T12:00:00.000000Z
# Server UUID: 12345678-1234-1234-1234-1234567890ab
# GTID_MODE: OFF
# Number of events: 0

2. 二进制日志事件类型 ​

  • 格式描述事件

    # at 4
#240101 12:00:00 server id 1  end_log_pos 123 CRC32 0x12345678 	Start: binlog v 4, server v 8.0.36 created 240101 12:00:00

  • 查询事件

    # at 123
#240101 12:00:00 server id 1  end_log_pos 234 CRC32 0x23456789 	Query	thread_id=4	exec_time=0	error_code=0
SET TIMESTAMP=1234567890/*!*/;
INSERT INTO test_table (name, value) VALUES ('test', 123)/*!*/;

  • 行事件

    # at 234
#240101 12:00:00 server id 1  end_log_pos 345 CRC32 0x34567890 	Table_map: `test`.`test_table` mapped to number 100
# at 345
#240101 12:00:00 server id 1  end_log_pos 456 CRC32 0x45678901 	Write_rows: table id 100 flags: STMT_END_F
### INSERT INTO `test`.`test_table`
### SET
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='test' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
###   @3=123 /* INT meta=0 nullable=1 is_null=0 */

  • 更新行事件

    # at 456
#240101 12:00:00 server id 1  end_log_pos 567 CRC32 0x56789012 	Update_rows: table id 100 flags: STMT_END_F
### UPDATE `test`.`test_table`
### WHERE
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='test' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
###   @3=123 /* INT meta=0 nullable=1 is_null=0 */
### SET
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='test' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
###   @3=456 /* INT meta=0 nullable=1 is_null=0 */

  • 删除行事件

    # at 567
#240101 12:00:00 server id 1  end_log_pos 678 CRC32 0x67890123 	Delete_rows: table id 100 flags: STMT_END_F
### DELETE FROM `test`.`test_table`
### WHERE
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='test' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
###   @3=456 /* INT meta=0 nullable=1 is_null=0 */

  • 事务事件

    # at 678
#240101 12:00:00 server id 1  end_log_pos 789 CRC32 0x78901234 	Xid = 12345
COMMIT/*!*/;

  • GTID 事件（MySQL 5.7+）

    # at 789
#240101 12:00:00 server id 1  end_log_pos 890 CRC32 0x89012345 	GTID	last_committed=0	sequence_number=1	rbr_only=yes
SET @@SESSION.GTID_NEXT= '12345678-1234-1234-1234-1234567890ab:1'/*!*/;

3. 二进制日志轮换 ​

  • 日志轮换事件
    # at 890
#240101 12:00:00 server id 1  end_log_pos 901 CRC32 0x90123456 	Rotate to mysql-bin.000002  pos: 4

中继日志 (Relay Log) ​

1. 中继日志条目格式 ​

  • 中继日志基本结构

    # Relay log name: relay-bin.000001
# Position: 4
# Binlog Version: 4
# Server Version: 8.0.36
# Start Time: 2024-01-01T12:00:00.000000Z
# End Time: 2024-01-01T12:00:00.000000Z
# Slave UUID: 87654321-4321-4321-4321-ba0987654321
# Number of events: 0

  • IO 线程状态

    # at 4
#240101 12:00:00 server id 1  end_log_pos 123 CRC32 0x12345678 	Start: binlog v 4, server v 8.0.36 created 240101 12:00:00

  • SQL 线程状态

    # at 123
#240101 12:00:00 server id 1  end_log_pos 234 CRC32 0x23456789 	Query	thread_id=4	exec_time=0	error_code=0
SET TIMESTAMP=1234567890/*!*/;
INSERT INTO test_table (name, value) VALUES ('test', 123)/*!*/;

2. 复制相关错误 ​

  • 主从连接失败

    2024-01-01T12:00:00.123456Z 1 [ERROR] [MY-010584] [Repl] Slave I/O for channel '': error connecting to master 'repl@master_host:3306' - retry-time: 60  retries: 1, Error_code: MY-002003

  • 中继日志损坏

    2024-01-01T12:00:00.123456Z 2 [ERROR] [MY-010586] [Repl] Error reading relay log event for channel '': slave SQL thread was killed

  • 复制冲突

    2024-01-01T12:00:00.123456Z 2 [ERROR] [MY-010600] [Repl] Error executing row event: 'Duplicate entry '1' for key 'PRIMARY''

日志分析工具 ​

1. 内置日志分析工具 ​

  • mysqlbinlog：用于查看和解析二进制日志

    bash
    # 查看二进制日志内容
mysqlbinlog mysql-bin.000001

# 按时间范围查看
mysqlbinlog --start-datetime="2024-01-01 12:00:00" --stop-datetime="2024-01-01 13:00:00" mysql-bin.000001

# 按位置查看
mysqlbinlog --start-position=100 --stop-position=200 mysql-bin.000001

  • mysqladmin：用于管理 MySQL 服务器，包括日志轮转

    bash
    # 轮转日志
mysqladmin flush-logs

# 查看服务器状态
mysqladmin status

2. 第三方日志分析工具 ​

  • pt-query-digest：Percona Toolkit 中的慢查询日志分析工具

    bash
    # 分析慢查询日志
pt-query-digest slow-query.log > slow_query_analysis.txt

# 分析二进制日志中的查询
pt-query-digest --type binlog mysql-bin.000001 > binlog_analysis.txt

  • mysqldumpslow：MySQL 自带的慢查询日志分析工具

    bash
    # 分析慢查询日志
mysqldumpslow slow-query.log

# 按查询次数排序
mysqldumpslow -s c slow-query.log

# 按查询时间排序
mysqldumpslow -s t slow-query.log

  • mytop：实时监控 MySQL 查询执行情况

    bash
    # 启动 mytop
mytop -u root -p password

日志分析最佳实践 ​

1. 日志配置建议 ​

  • 错误日志

    • 启用错误日志，设置合适的日志级别
    • 定期轮换错误日志，避免文件过大
    • 监控错误日志中的关键错误信息

  • 查询日志

    • 生产环境中一般禁用查询日志，避免性能影响
    • 仅在调试或性能分析时临时启用
    • 启用时设置合适的日志格式和输出方式

  • 慢查询日志

    • 生产环境中建议启用慢查询日志
    • 设置合适的慢查询阈值（如 1 秒）
    • 定期分析慢查询日志，优化查询
    • 考虑使用性能模式（Performance Schema）替代慢查询日志

  • 二进制日志

    • 启用二进制日志，用于复制和恢复
    • 设置合适的二进制日志格式（ROW、STATEMENT 或 MIXED）
    • 定期轮换二进制日志，设置合理的过期时间

2. 日志监控和告警 ​

  • 关键错误监控

    • 监控错误日志中的 FATAL、ERROR 级别信息
    • 针对特定错误（如死锁、连接数超限）设置告警
    • 使用监控工具（如 Prometheus、Zabbix）进行实时监控

  • 慢查询监控

    • 监控慢查询数量和平均执行时间
    • 针对频繁出现的慢查询设置告警
    • 定期生成慢查询报告

  • 日志文件监控

    • 监控日志文件大小，避免磁盘空间不足
    • 监控日志文件生成速率，识别异常情况
    • 定期备份日志文件，用于后续分析

3. 日志分析流程 ​

  • 实时监控

    • 使用实时监控工具监控日志中的关键信息
    • 设置告警规则，及时发现问题

  • 定期分析

    • 每日：检查错误日志中的关键错误
    • 每周：分析慢查询日志，优化查询
    • 每月：进行全面的日志分析，评估系统运行状况

  • 故障诊断

    • 发生故障时，首先查看错误日志
    • 根据错误信息定位问题根源
    • 使用二进制日志进行数据恢复（如需要）

常见问题（FAQ） ​

Q1: 如何启用和配置 MySQL 日志？ ​

A1: MySQL 日志配置方法：

  • 在配置文件（my.cnf 或 my.ini）中设置相关参数
  • 或使用 SET GLOBAL 命令动态启用（部分日志类型）

主要日志配置参数：

  • 错误日志：log_error
  • 查询日志：general_log, general_log_file
  • 慢查询日志：slow_query_log, slow_query_log_file, long_query_time
  • 二进制日志：log_bin, binlog_format, expire_logs_days

Q2: 生产环境中应该启用哪些日志？ ​

A2: 生产环境日志启用建议：

  • 必须启用：错误日志、二进制日志
  • 建议启用：慢查询日志（设置合适的阈值）
  • 一般禁用：查询日志（性能影响较大）

Q3: 如何分析慢查询日志？ ​

A3: 慢查询日志分析步骤：

  1. 使用 mysqldumpslow 或 pt-query-digest 工具分析
  2. 识别频繁出现的慢查询
  3. 查看执行计划，优化索引和查询
  4. 监控优化后的效果

Q4: 二进制日志有什么作用？ ​

A4: 二进制日志的主要作用：

  • 数据恢复：用于恢复到特定时间点
  • 主从复制：从库通过二进制日志同步主库数据
  • 审计：记录所有数据变更操作

Q5: 如何轮换 MySQL 日志？ ​

A5: 日志轮换方法：

  • 自动轮换：设置 expire_logs_days 参数
  • 手动轮换：使用 FLUSH LOGS 命令或 mysqladmin flush-logs
  • 配置 logrotate 工具进行日志轮换

Q6: 日志文件过大怎么办？ ​

A6: 处理大日志文件的方法：

  • 启用日志轮换，定期生成新的日志文件
  • 压缩旧日志文件，节省磁盘空间
  • 调整日志级别，减少不必要的日志输出
  • 考虑使用日志收集系统（如 ELK Stack）集中管理日志

Q7: 如何从二进制日志恢复数据？ ​

A7: 从二进制日志恢复数据步骤：

  1. 使用 mysqlbinlog 工具解析二进制日志
  2. 提取需要恢复的 SQL 语句
  3. 在目标数据库中执行这些 SQL 语句
  4. 验证恢复的数据完整性

Q8: 如何监控 MySQL 日志？ ​

A8: MySQL 日志监控方法：

  • 使用内置的 SHOW LOGS 命令查看日志信息
  • 使用第三方监控工具（如 Prometheus、Zabbix）
  • 配置日志告警规则，及时发现异常
  • 使用日志分析工具定期生成报告

Q9: 慢查询日志中的 Lock_time 是什么意思？ ​

A9: Lock_time 表示查询在执行过程中等待锁的时间：

  • 包括表锁和行锁的等待时间
  • 不包括查询执行时间
  • 高 Lock_time 通常表示存在锁竞争问题

Q10: 如何区分二进制日志中的不同事件类型？ ​

A10: 二进制日志事件类型识别：

  • 使用 mysqlbinlog 工具查看，每个事件都有明确的类型标识
  • 常见事件类型：Query_event、Table_map_event、Write_rows_event、Update_rows_event、Delete_rows_event、Xid_event
  • 不同事件类型对应不同的数据变更操作

不同 MySQL 版本的日志差异 ​

MySQL 5.6 vs 5.7 ​

  • 慢查询日志增强

    • MySQL 5.7 增加了更多慢查询日志信息（如 Full_scan、Tmp_table 等）
    • 支持将慢查询日志写入表（mysql.slow_log）

  • 二进制日志增强

    • MySQL 5.7 引入了 GTID 支持
    • 增强了二进制日志的安全性
    • 支持更多的二进制日志格式选项

MySQL 5.7 vs 8.0 ​

  • 日志格式变化

    • MySQL 8.0 改进了错误日志格式，增加了更多上下文信息
    • 慢查询日志增加了更多执行计划相关信息

  • 新的日志类型

    • MySQL 8.0 引入了审计日志（Audit Log）作为企业版功能
    • 增强了性能模式（Performance Schema），可替代部分日志功能

  • 日志安全性增强

    • MySQL 8.0 支持二进制日志加密
    • 增强了日志的访问控制
    • 支持更多的日志校验算法

通过对 MySQL 各种日志条目的了解和分析，可以帮助数据库管理员更好地监控、诊断和优化 MySQL 数据库的运行状况。定期分析日志是数据库运维的重要组成部分，能够及时发现潜在问题并采取相应的措施。