日志管理
错误日志
# 查看错误日志路径
mysql> select @@log_error;
+----------------------------+
| @@log_error |
+----------------------------+
| /data/mysql/data/mysql.log |
+----------------------------+
二进制日志
作用：用于即时点的数据恢复、主从复制
配置二进制日志（默认没有开启）
# 日志要和数据分开存放
log_bin # 开关、设定存放位置
server_id # 5.6单机不需要此参数，5.7必须要加
[root@localhost ~]# mkdir /data/binlog -p
[root@localhost ~]# chown -R mysql. /data/
[root@localhost ~]# vim /etc/my.cnf
[mysqld]
user=mysql
basedir=/application/mysql
datadir=/data/mysql/data
socket=/tmp/mysql.sock
server_id=6
port=3306
log_error=/data/mysql/data/mysql.log
log_bin=/data/binlog/mysql-bin
server_id=6
secure-file-priv=/tmp
[mysql]
socket=/tmp/mysql.sock
[root@localhost ~]# /etc/init.d/mysqld restart
Shutting down MySQL.. SUCCESS!
Starting MySQL. SUCCESS!
[root@localhost ~]# ls /data/binlog/
mysql-bin.000001 mysql-bin.000002 mysql-bin.000003 mysql-bin.index
# 查看binlog的位置
mysql> show variables like '%log_bin%';
+---------------------------------+------------------------------+
| Variable_name | Value |
+---------------------------------+------------------------------+
| log_bin | ON |
| log_bin_basename | /data/binlog/mysql-bin |
| log_bin_index | /data/binlog/mysql-bin.index |
| log_bin_trust_function_creators | OFF |
| log_bin_use_v1_row_events | OFF |
| sql_log_bin | ON |
+---------------------------------+------------------------------+
binlog记录了什么？
记录了数据库中所有变更类的操作：DDL DCL DML
- 对于DDL和DCL语句，记录发生过的语句
- 对于DML语句（insert update delete）：必须是已经提交的事务。
# 记录格式（5.6以后默认级别就是ROW模式） ROW RBR 行记录模式 逐行记录 日志量大且严谨 STATEMENT SBR 语句记录模式 只记录语句本身 日志量小，可读性强（对于函数类的操作会出现记录错误的情况） MIXED MBR 混合记录模式 # 查看二进制日志默认的存储格式 mysql> select @@binlog_format; +-----------------+ | @@binlog_format | +-----------------+ | ROW | +-----------------+
二进制日志事件（event）
二进制日志的最小记录单元
对于DDL，DCL，一个语句就是一个event
对于DML来说，只记录已经提交的事务。
position号码
begin; 120 - 340
DML1 340 - 460
DML2 460 - 550
commit; 550 - 760
查看二进制日志
# 查看数据库使用的二进制日志
mysql> show binary logs;
+------------------+-----------+
| Log_name | File_size |
+------------------+-----------+
| mysql-bin.000001 | 177 |
| mysql-bin.000002 | 177 |
| mysql-bin.000003 | 177 |
| mysql-bin.000004 | 177 |
| mysql-bin.000005 | 154 |
+------------------+-----------+
# 查看数据库正在使用的二进制日志文件
mysql> show master status;
+------------------+----------+--------------+------------------+-------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------------+----------+--------------+------------------+-------------------+
| mysql-bin.000005 | 154 | | | |
+------------------+----------+--------------+------------------+-------------------+
# 查看000005二进制日志的事件
mysql> show binlog events in 'mysql-bin.000005';
+------------------+-----+----------------+-----------+-------------+---------------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+------------------+-----+----------------+-----------+-------------+---------------------------------------+
| mysql-bin.000005 | 4 | Format_desc | 6 | 123 | Server ver: 5.7.26-log, Binlog ver: 4 |
| mysql-bin.000005 | 123 | Previous_gtids | 6 | 154 | |
| mysql-bin.000005 | 154 | Anonymous_Gtid | 6 | 219 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |
| mysql-bin.000005 | 219 | Query | 6 | 322 | create database oldboy2 |
+------------------+-----+----------------+-----------+-------------+---------------------------------------+
Log_name 日志名
Pos 事件开始的position ***
Event_type 事件类型
Server_id 发生在哪台机器的事件
End_log_pos 事件结束的位置号 ***
Info 事件内容 ***
# 二进制日志内容查看
[root@localhost binlog]# mysqlbinlog mysql-bin.000005
# 普通查看
[root@localhost binlog]# mysqlbinlog mysql-bin.000005 | grep -v "SET" >/tmp/aa.txt
# 详细查看
[root@localhost binlog]# mysqlbinlog --base64-output=decode-rows -vvv mysql-bin.000005
# 按需截取二进制日志
基于position号的截取：核心在于找起点和终点
--start-position=###
--stop-position=###
截取
[root@localhost binlog]# mysqlbinlog --start-position=219 --stop-position=322 /data/binlog/mysql-bin.000005 >/tmp/bin.sql
恢复(mysql> drop database oldboy2;)
mysql> drop database oldboy2;
Query OK, 0 rows affected (0.00 sec)
mysql> set sql_log_bin=0; # 进制恢复过程中再次产生日志信息（临时性的，只影响当前会话，关闭窗口就会消失）
Query OK, 0 rows affected (0.00 sec)
mysql> source /tmp/bin.sql
案例恢复详解
create database test charset utf8mb4; #起始
use test;
create table t1 (id int);
insert into t1 values(1);
commit;
insert into t1 values(2);
commit;
insert into t1 values(3);
commit; # 结束
drop database test;
# 首先查询到建库语句的position
mysql> show binlog events in 'mysql-bin.000005';
+------------------+------+----------------+-----------+-------------+---------------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+------------------+------+----------------+-----------+-------------+---------------------------------------+
| mysql-bin.000005 | 4 | Format_desc | 6 | 123 | Server ver: 5.7.26-log, Binlog ver: 4 |
| mysql-bin.000005 | 123 | Previous_gtids | 6 | 154 | |
| mysql-bin.000005 | 154 | Anonymous_Gtid | 6 | 219 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |
| mysql-bin.000005 | 219 | Query | 6 | 322 | create database oldboy2 |
| mysql-bin.000005 | 322 | Anonymous_Gtid | 6 | 387 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |
| mysql-bin.000005 | 387 | Query | 6 | 478 | drop database oldboy2 |
| mysql-bin.000005 | 478 | Anonymous_Gtid | 6 | 543 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |
| mysql-bin.000005 | 543 | Query | 6 | 653 | create database test charset utf8mb4 |
| mysql-bin.000005 | 653 | Anonymous_Gtid | 6 | 718 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |
| mysql-bin.000005 | 718 | Query | 6 | 816 | use `test`; create table t1 (id int) |
| mysql-bin.000005 | 816 | Anonymous_Gtid | 6 | 881 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |
| mysql-bin.000005 | 881 | Query | 6 | 953 | BEGIN |
| mysql-bin.000005 | 953 | Table_map | 6 | 998 | table_id: 109 (test.t1) |
| mysql-bin.000005 | 998 | Write_rows | 6 | 1038 | table_id: 109 flags: STMT_END_F |
| mysql-bin.000005 | 1038 | Xid | 6 | 1069 | COMMIT /* xid=46 */ |
| mysql-bin.000005 | 1069 | Anonymous_Gtid | 6 | 1134 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |
| mysql-bin.000005 | 1134 | Query | 6 | 1206 | BEGIN |
| mysql-bin.000005 | 1206 | Table_map | 6 | 1251 | table_id: 109 (test.t1) |
| mysql-bin.000005 | 1251 | Write_rows | 6 | 1291 | table_id: 109 flags: STMT_END_F |
| mysql-bin.000005 | 1291 | Xid | 6 | 1322 | COMMIT /* xid=48 */ |
| mysql-bin.000005 | 1322 | Anonymous_Gtid | 6 | 1387 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |
| mysql-bin.000005 | 1387 | Query | 6 | 1459 | BEGIN |
| mysql-bin.000005 | 1459 | Table_map | 6 | 1504 | table_id: 109 (test.t1) |
| mysql-bin.000005 | 1504 | Write_rows | 6 | 1544 | table_id: 109 flags: STMT_END_F |
| mysql-bin.000005 | 1544 | Xid | 6 | 1575 | COMMIT /* xid=50 */ |
| mysql-bin.000005 | 1575 | Anonymous_Gtid | 6 | 1640 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |
| mysql-bin.000005 | 1640 | Query | 6 | 1732 | drop database test |
+------------------+------+----------------+-----------+-------------+---------------------------------------+
# 找到发现position区间段是
543 - 1640
# 截取日志
[root@localhost binlog]# mysqlbinlog --start-position=543 --stop-position=1640 /data/binlog/mysql-bin.000005 >/tmp/bak.sql
# 进行恢复
mysql> set sql_log_bin=0;
Query OK, 0 rows affected (0.00 sec)
mysql> source /tmp/bak.sql
# 恢复后查看数据进行验证
mysql> show databases;
+--------------------+
| Database |
+--------------------+
| information_schema |
| mysql |
| oldboy |
| oldboy2 |
| performance_schema |
| school |
| sys |
| test |
| world |
| zrblog |
+--------------------+
10 rows in set (0.00 sec)
mysql> use test;
Database changed
mysql> select * from t1;
+------+
| id |
+------+
| 1 |
| 2 |
| 3 |
+------+
3 rows in set (0.00 sec)
GTID
基于position号恢复需要多次截取，找起点和终点的过程是很复杂的。
什么是GTID(全局事务编号:DDL DCL DML(begin->commit))
5.6版本新加的特性，5.7中做了加强
5.6中默认不开启，5.7中默认也不开启。
GTID = source_id : transaction_id
开启GTID功能
vim /etc/my.cnf
gtid-mode=on
enforce-gtid-consistency=true
查看GTID
create database gg;
use gg;
create table t1(id int);
insert into t1 values(1);
commit;
insert into t1 values(2);
commit;
insert into t1 values(3);
commit;
mysql> show master status;
+------------------+----------+--------------+------------------+------------------------------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------------+----------+--------------+------------------+------------------------------------------+
| mysql-bin.000006 | 1212 | | | f98d1e0b-a7e4-11eb-8259-080027fb878b:1-5 |
+------------------+----------+--------------+------------------+------------------------------------------+
mysql> drop database gg;
Query OK, 1 row affected (0.00 sec)
mysql> show binlog events in 'mysql-bin.000006';
+------------------+------+----------------+-----------+-------------+-------------------------------------------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+------------------+------+----------------+-----------+-------------+-------------------------------------------------------------------+
| mysql-bin.000006 | 4 | Format_desc | 6 | 123 | Server ver: 5.7.26-log, Binlog ver: 4 |
| mysql-bin.000006 | 123 | Previous_gtids | 6 | 154 | |
| mysql-bin.000006 | 154 | Gtid | 6 | 219 | SET @@SESSION.GTID_NEXT= 'f98d1e0b-a7e4-11eb-8259-080027fb878b:1' |
| mysql-bin.000006 | 219 | Query | 6 | 307 | create database gg |
| mysql-bin.000006 | 307 | Gtid | 6 | 372 | SET @@SESSION.GTID_NEXT= 'f98d1e0b-a7e4-11eb-8259-080027fb878b:2' |
| mysql-bin.000006 | 372 | Query | 6 | 465 | use `gg`; create table t1(id int) |
| mysql-bin.000006 | 465 | Gtid | 6 | 530 | SET @@SESSION.GTID_NEXT= 'f98d1e0b-a7e4-11eb-8259-080027fb878b:3' |
| mysql-bin.000006 | 530 | Query | 6 | 600 | BEGIN |
| mysql-bin.000006 | 600 | Table_map | 6 | 643 | table_id: 108 (gg.t1) |
| mysql-bin.000006 | 643 | Write_rows | 6 | 683 | table_id: 108 flags: STMT_END_F |
| mysql-bin.000006 | 683 | Xid | 6 | 714 | COMMIT /* xid=10 */ |
| mysql-bin.000006 | 714 | Gtid | 6 | 779 | SET @@SESSION.GTID_NEXT= 'f98d1e0b-a7e4-11eb-8259-080027fb878b:4' |
| mysql-bin.000006 | 779 | Query | 6 | 849 | BEGIN |
| mysql-bin.000006 | 849 | Table_map | 6 | 892 | table_id: 108 (gg.t1) |
| mysql-bin.000006 | 892 | Write_rows | 6 | 932 | table_id: 108 flags: STMT_END_F |
| mysql-bin.000006 | 932 | Xid | 6 | 963 | COMMIT /* xid=12 */ |
| mysql-bin.000006 | 963 | Gtid | 6 | 1028 | SET @@SESSION.GTID_NEXT= 'f98d1e0b-a7e4-11eb-8259-080027fb878b:5' |
| mysql-bin.000006 | 1028 | Query | 6 | 1098 | BEGIN |
| mysql-bin.000006 | 1098 | Table_map | 6 | 1141 | table_id: 108 (gg.t1) |
| mysql-bin.000006 | 1141 | Write_rows | 6 | 1181 | table_id: 108 flags: STMT_END_F |
| mysql-bin.000006 | 1181 | Xid | 6 | 1212 | COMMIT /* xid=14 */ |
| mysql-bin.000006 | 1212 | Gtid | 6 | 1277 | SET @@SESSION.GTID_NEXT= 'f98d1e0b-a7e4-11eb-8259-080027fb878b:6' |
| mysql-bin.000006 | 1277 | Query | 6 | 1363 | drop database gg |
+------------------+------+----------------+-----------+-------------+-------------------------------------------------------------------+
23 rows in set (0.01 sec)
# 正确截取方式
[root@localhost binlog]# mysqlbinlog --skip-gtids --include-gtids='f98d1e0b-a7e4-11eb-8259-080027fb878b:1-5' /data/binlog/mysql-bin.000006 >/tmp/gtid.sql
# 以下截取出来的gtid日志不能直接恢复，为啥呢？ 因为幂等性
[root@localhost binlog]# mysqlbinlog --include-gtids='f98d1e0b-a7e4-11eb-8259-080027fb878b:1-5' /data/binlog/mysql-bin.000006 >/tmp/gtid.sql
# 恢复数据
mysql> set sql_log_bin=0;
Query OK, 0 rows affected (0.00 sec)
mysql> source /tmp/gtid.sql
mysql> show databases;
mysql> use gg;
Database changed
mysql> select * from t1;
+------+
| id |
+------+
| 1 |
| 2 |
| 3 |
+------+
# 跳过某些gtid不截取
2和4 2,4
2至4 2-4
mysqlbinlog --include-gtids='f98d1e0b-a7e4-11eb-8259-080027fb878b:1-5' /data/binlog/mysql-bin.000006 --exclude-gtids='f98d1e0b-a7e4-11eb-8259-080027fb878b:2' >/tmp/gtid.sql
mysqlbinlog --include-gtids='f98d1e0b-a7e4-11eb-8259-080027fb878b:1-5' /data/binlog/mysql-bin.000006 --exclude-gtids='f98d1e0b-a7e4-11eb-8259-080027fb878b:2,f98d1e0b-a7e4-11eb-8259-080027fb878b:4' >/tmp/gtid.sql
二进制日志其他操作
# 临时关闭二进制日志（会话级别）做数据恢复之前可以使用
set sql_log_bin=0;
# 自动清理 :设置依据？ 至少是一个全备份的周期。企业建议2个全备份周期+1
mysql> select @@expire_logs_days;
+--------------------+
| @@expire_logs_days |
+--------------------+
| 0 |
+--------------------+
临时设置
mysql> set global expire_logs_days=8; # 7天是全备周期，所以可以设置为8天
永久设置
vim /etc/my.cnf
expire_logs_days=8
# 手工清理
PURGE BINARY LOGS BEFORE now() - INTERVAL 3day; # 删除三天之前的日子
PURGE BINARY LOGS TO 'mysql-bin.000010'; # 删除到那个日志文件为止
删除数据库所有日志文件，并且从000001开始
reset master; #非常危险，千万不要用，主从架构会崩溃
# 日志滚动（从000001重新开始）
1.重启数据库
2.或者用 flush logs 命令
mysql> show variables like '%max_binlog_size%'; #默认值是 1GB
+-----------------+------------+
| Variable_name | Value |
+-----------------+------------+
| max_binlog_size | 1073741824 |
+-----------------+------------+
slowlog
开启慢日志（默认没开启）
slow_query_log=1 #开关
slow_query_log_file=/data/mysql/data/slow.log #位置
long_query_time=0.1 #设定慢查询时间
log_queries_not_using_indexes #没走索引的语句也记录
压测
[root@localhost binlog]# mysqlslap --defaults-file=/etc/my.cnf --concurrency=100 --iterations=1 --create-schema='oldboy' --query="select * from oldboy.t100w where k2='xyMN'" engine=innodb --number-of-queries=2000 -uroot -p123 -verbose
查看慢日志
[root@localhost binlog]# cat /data/mysql/data/slow.log
/application/mysql/bin/mysqld, Version: 5.7.26-log (MySQL Community Server (GPL)). started with:
Tcp port: 3306 Unix socket: /tmp/mysql.sock
Time Id Command Argument
# Time: 2021-05-07T08:27:33.281983Z
# User@Host: root[root] @ localhost [] Id: 33
# Query_time: 0.173121 Lock_time: 0.000015 Rows_sent: 257 Rows_examined: 257
use oldboy;
SET timestamp=1620376053;
select * from oldboy.t100w where k2='xyMN';
# Time: 2021-05-07T08:27:33.283401Z
# User@Host: root[root] @ localhost [] Id: 47
# Query_time: 0.259220 Lock_time: 0.087784 Rows_sent: 257 Rows_examined: 257
SET timestamp=1620376053;
select * from oldboy.t100w where k2='xyMN';
# Time: 2021-05-07T08:27:33.288964Z
分析慢日志
# mysqldumpslow 分析慢日志
[root@localhost binlog]# mysqldumpslow -s c -t 10 /data/mysql/data/slow.log
Reading mysql slow query log from /data/mysql/data/slow.log
Count: 17 Time=0.18s (3s) Lock=0.02s (0s) Rows=257.0 (4369), root[root]@localhost
select * from oldboy.t100w where k2='S'
# percona-toolkit 工具使用
下载地址 https://www.percona.com/downloads/percona-toolkit/LATEST/
percona-toolkit-3.3.1-1.el7.x86_64
[root@localhost software]# yum install -y percona-toolkit-3.3.1-1.el7.x86_64.rpm
[root@localhost software]# pt-query-digest /data/mysql/data/slow.log
*******************************************************************
Using the default of SSL_verify_mode of SSL_VERIFY_NONE for client
is deprecated! Please set SSL_verify_mode to SSL_VERIFY_PEER
possibly with SSL_ca_file|SSL_ca_path for verification.
If you really don't want to verify the certificate and keep the
connection open to Man-In-The-Middle attacks please set
SSL_verify_mode explicitly to SSL_VERIFY_NONE in your application.
*******************************************************************
at /usr/bin/pt-query-digest line 12054.
*******************************************************************
Using the default of SSL_verify_mode of SSL_VERIFY_NONE for client
is deprecated! Please set SSL_verify_mode to SSL_VERIFY_PEER
possibly with SSL_ca_file|SSL_ca_path for verification.
If you really don't want to verify the certificate and keep the
connection open to Man-In-The-Middle attacks please set
SSL_verify_mode explicitly to SSL_VERIFY_NONE in your application.
*******************************************************************
at /usr/bin/pt-query-digest line 12054.
# A software update is available:
# 100ms user time, 10ms system time, 28.86M rss, 241.93M vsz
# Current date: Fri May 7 16:45:19 2021
# Hostname: localhost.localdomain
# Files: /data/mysql/data/slow.log
# Overall: 17 total, 1 unique, 0 QPS, 0x concurrency _____________________
# Time range: all events occurred at 2021-05-07T08:27:33
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 3s 102ms 420ms 200ms 266ms 70ms 189ms
# Lock time 287ms 13us 126ms 17ms 87ms 37ms 18us
# Rows sent 4.27k 257 257 257 257 0 257
# Rows examine 4.27k 257 257 257 257 0 257
# Query size 714 42 42 42 42 0 42
# Profile
# Rank Query ID Response time Calls R/Call V/M
# ==== =================================== ============= ===== ====== ====
# 1 0x617AC0C2E2FB389D0CF91886EB3F68F0 3.3916 100.0% 17 0.1995 0.02 SELECT oldboy.t?w
# Query 1: 0 QPS, 0x concurrency, ID 0x617AC0C2E2FB389D0CF91886EB3F68F0 at byte 3959
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.02
# Time range: all events occurred at 2021-05-07T08:27:33
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 100 17
# Exec time 100 3s 102ms 420ms 200ms 266ms 70ms 189ms
# Lock time 100 287ms 13us 126ms 17ms 87ms 37ms 18us
# Rows sent 100 4.27k 257 257 257 257 0 257
# Rows examine 100 4.27k 257 257 257 257 0 257
# Query size 100 714 42 42 42 42 0 42
# String:
# Databases oldboy
# Hosts localhost
# Users root
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms ################################################################
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `oldboy` LIKE 't100w'\G
# SHOW CREATE TABLE `oldboy`.`t100w`\G
# EXPLAIN /*!50100 PARTITIONS*/
select * from oldboy.t100w where k2='xyMN'\G