MySQL训练营-慢查询诊断问题

slow_query_log + long_query_time

slow_query_log：日志开关，是否记慢查询日志

long_query_time：超过多长时间判定为慢查询

查看参数设置：

SHOW VARIABLES LIKE ‘slow_query_log’;
SHOW VARIABLES LIKE ‘long_query_time’;

实践建议：

set global long_query_time=1;
分析型业务，set long_query_time=N;

全局设置为1，session级别针对耗时的分析型业务可以设置时间更长一点。

生成并查看一条慢查询日志：

先将slow_query_log开关打开：set global slow_query_log= on;，只能使用global级别。

再将long_query_time时间设置为1s：set global long_query_time= 1;或set long_query_time= 1;都行。

在终端中执行select sleep(10);，slow_query.log文件可以看到：

/usr/sbin/mysqld, Version: 8.0.18 (MySQL Community Server - GPL). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
# Time: 2024-12-22T03:32:41.457742Z
# User@Host: root[root] @ localhost [127.0.0.1]  Id:    10
# Query_time: 10.000678  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 1
SET timestamp=1734838351;
select sleep(10);

Query_time: 10.000678

表示整个查询从开始执行到执行完毕所花费的总时间，单位是秒。在这个例子中，查询总共耗时 10.000678 秒。
Lock_time: 0.000000

指的是该查询在获取锁资源上所花费的时间，单位同样是秒。这里显示为 0 秒，意味着这个查询在执行过程中基本没有因为等待获取锁而耗费时间，即没有遇到锁等待的情况，能直接获取到所需的锁进行后续的操作。
Rows_sent: 1

代表查询最终返回给客户端的行数。此例中返回了 1 行数据给客户端，说明查询结果的数据量比较小，不过查询耗时却很长，这就提示可能是查询执行过程中的其他环节（比如函数执行等情况）导致了整体的缓慢，而非数据量太大需要大量传输的原因。
Rows_examined: 1

表示查询执行过程中数据库引擎扫描的数据行数。这里扫描了 1 行，结合返回行数等情况可以分析出数据库在执行该查询时的数据访问规模。

log_slow_extra

在MySQL中，log_slow_extra是一个与慢查询日志（Slow Query Log）相关的参数。它用于控制在慢查询日志中是否记录额外的信息。这些额外信息可以帮助数据库管理员（DBA）更深入地了解查询性能问题的原因。

同样的可以查看参数设置：

SHOW VARIABLES LIKE ‘log_slow_extra’;

实践建议：

打开参数后，CPU、内存、磁盘占用会比更多。但是可以提供更多的定位信息，建议稳定后打开。

5.7 和 8.0 关于慢查询日志差异

前值准备（建表准备数据）：

drop table if exists t;

CREATE TABLE t (
    id INT PRIMARY KEY AUTO_INCREMENT,
    c INT
);

INSERT INTO t (c) VALUES (0), (0);

场景：

session1	session2
begin; update t set c=1 where id=1;
	update t set c=2 where id=1; //blocked
select sleep(10); commit;
	//updated,affected rows=1

问：session2是否记录慢查询？

老师课上给的答案：5.7不会记，MySql会扣除行锁时间。8.0会记录。(答案存疑)

先使用mysql:8.0.18进行测试，慢查询日志中只有执行sleep(10)的记录：

怀疑是mysql的问题，再使用mysql:8.0.40进行测试，能复现该场景：

可见是mysql:8.0.x某个小版本引入的新特性，非mysql:8.0版本都有的。

样例分析(MySQL 8.0)

session1	session2	session3
	lock table t write
begin; update t set c=c+1 where id=1;
		begin; update t set c=c*10 where id=1;
	unlock table;
commit;

解锁后，先执行session1再执行session3。session1先获取到锁应该是，等待时间比session3长。

慢日志：

# Time: 2024-12-25T13:43:04.675707Z
# User@Host: root[root] @ localhost []  Id:     9
# Query_time: 37.684517  Lock_time: 0.000004 Rows_sent: 0  Rows_examined: 1
SET timestamp=1735134146;
update t set c=c+1 where id=1;
# Time: 2024-12-25T13:43:19.938977Z
# User@Host: root[root] @ localhost []  Id:    13
# Query_time: 43.321374  Lock_time: 15.263238 Rows_sent: 0  Rows_examined: 1
SET timestamp=1735134156;
update t set c=c*10 where id=1;

可知Lock_time中只记录了行锁的等待时间。即Query_time-Lock_time不仅包括SQL语句的执行时间，还包括等待表锁的时间。

log_queries_not_using_indexes

log_queries_not_using_indexes是 MySQL 中的一个参数。当这个参数设置为ON时，MySQL 会将没有使用索引的查询语句记录到慢查询日志（slow query log）中。

前置准备：

drop table if exists t;

CREATE TABLE t(
    id int NOT NULL,
    c int DEFAULT NULL,
    d int DEFAULT NULL,
    e int DEFAULT NULL,
    PRIMARY KEY(id ),
    KEY c(c),
    KEY d(d)
);

insert into t values(1,833,10,1),(2,2,2,2),(3,3,3,3);

练习：update t set e=e*10 where e = 2;锁多少行？

答案锁全表，可以在一个实物中更新update t set e=e*10 where e = 2;，另一个事物执行update t set e=e*10 where e = 1;可以看到在等待：

session1	session2
begin; update t set e=e*10 where e = 1;
	update t set e=e*10 where id = 2;

在默认隔离级别（可重复读）下，会阻塞锁全表。在读提交下，不会阻塞。

可以查看：https://tech.meituan.com/2014/08/20/innodb-lock.html，了解锁释放的实际。

通过刚刚的例子，可以看到没有走索引的语句会存在潜在的风险，所以这个参数建议打开。

那么，参数打开后导致慢查询日志过多，如以下对系统表的查询也会记录慢日志：

select * from information_schema.processlist;
select * from information_schema.innodb_trx;
show engine innodb status\G # 实测不会记

解决办法：

log_queries_not_using_indexes+log_throttle_queries_not_using_indexes
log_throttle_queries_not_using_indexes:限制每分钟无主键语句的记录条数上限。容易误伤需要记录的慢查询日志。
log_queries_not_using_indexes+min_examined_row_limit
min_examined_row_limit:扫描行数少于这个值的语句，不记入慢查询日志。

方案2，是否可行？先分析select count(*) from t;在8.0.17版本以前是3，新版本为0。新版本优化为由存储层计算结果直接返回给SQL层。

# Time: 2024-12-25T14:15:46.264553Z
# User@Host: root[root] @ localhost []  Id:    12
# Query_time: 40.595383  Lock_time: 0.000006 Rows_sent: 1  Rows_examined: 0
SET timestamp=1735136105;
select count(*) from t;

所以方案2会导致，该语句不记录。此外在以下场景：

先创建表与存储过程：

drop table if exists t;

CREATE TABLE t (
    id INT,
    c INT
);

INSERT INTO t (id, c) VALUES (0,0), (1,0), (2,0), (3,0), (4,0);

//准备一个存储过程，对id=3这一行做5万次更新
delimiter ;;
create procedure udata3() begin
declare i int; set i=1; while(i<=50000) do
    update t set c=c+1 where id=3;
    set i=i+1;
end while;
end;;
delimiter ;

再进行以下操作：

session1(隔离级别RR)	session2
begin; select * from t where id = 1;
	call udata3();
select * from t where id = 3; // 查询Q

可以在 MySQL 客户端连接到数据库后，使用SET语句来设置当前会话的事务隔离级别为 RR，示例代码如下：
-- 设置当前会话的事务隔离级别为RR
SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ;

-- 开始事务
START TRANSACTION;
-- 这里编写事务中的SQL语句，例如查询、插入、更新等操作
SELECT * FROM your_table;
-- 提交事务
COMMIT;

查询Q的row_examined是多少？

为1，存储层最会返回最新的一行数据

查询Q的的查询时间更接近那个数值？

A：0.01s B：1.01s

答案是B，现在数据库都实现了MVCC会保留历史版本，为了找到最新的数据会从最新的版本遍历找到最老的版本(可重复读隔离级别)。

测试结果：

# Time: 2025-01-08T12:28:58.505518Z
# User@Host: root[root] @ localhost []  Id:    15
# Query_time: 0.000387  Lock_time: 0.000004 Rows_sent: 1  Rows_examined: 5
SET timestamp=1736339338;
select * from t where id = 1;

# Time: 2025-01-08T12:32:38.671135Z
# User@Host: root[root] @ localhost []  Id:    16
# Query_time: 209.297586  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 250000
SET timestamp=1736339558;
call udata3();

# Time: 2025-01-08T12:33:16.075252Z
# User@Host: root[root] @ localhost []  Id:    15
# Query_time: 0.058057  Lock_time: 0.000004 Rows_sent: 1  Rows_examined: 5
SET timestamp=1736339596;
select * from t where id = 3;

可以看到执行查询时间虽然没有1s那么夸张，但是也用了0.058s。也比执行存储过程前的0.0003慢了很多。这种情况也应该记录慢查询日志，但是因为min_examined_row_limit的配置可能不记录日志。

生产建议：min_examined_row_limit不应该在生产环境上设置。

内核改进思路(Mysql官方不提供)：

set global log_queries_not_using_indexes_white_user = ‘xxx’ (模拟)

白名单管理，将监控相关的用户查询屏蔽。

改为 global,session 变量

set global log_queries_not_using_indexes=on 监控应用端:

set log_queries_not_using_indexes=off(模拟)

生产建议：根据业务情况可以先不开，稳定后打开。

慢查询影响性能嘛？

慢查询日志影响性能吗?

A. 影响 B. 不影响

A

执行错误的语句记不记入慢查询日志?

A. 记录 B. 不记录

A

如何验证？

锁等待，A线程开启事务，更新一行。B线程更新同一行，会报错。验证结果：

# Time: 2025-01-08T13:01:37.382271Z
# User@Host: root[root] @ localhost []  Id:    15
# Query_time: 0.000530  Lock_time: 0.000004 Rows_sent: 0  Rows_examined: 5
SET timestamp=1736341297;
update t set c=c+1 where id=3;
# Time: 2025-01-08T13:02:30.110640Z
# User@Host: root[root] @ localhost []  Id:    16
# Query_time: 50.019117  Lock_time: 50.018677 Rows_sent: 0  Rows_examined: 0
SET timestamp=1736341300;
update t set c=c+1 where id=3;

慢查询日志是在语句执行的哪个阶段写入的?

A. 语句执行开始阶段 B. 语句执行结束，发查询结果给客户端前 C. 语句执行结束，发查询结果给客户端后

C

可以使用下面方法测试：

gdb -p <pid of mysqld>
(gdb) b my_error
(gdb) c
root@devops_db 15:07: [test]> select a;

看此时slow log还没有输出 select a 这个语句

结论:slowlog 是在语句结果返回给客户端后再输出的

疑问:那为什么开slow log会影响性能?

因为在记录慢日志时，线程无法处理新来的请求。

怎么减少突发慢查询对系统的影响

提前发现慢查询

业务回归测试时提前发现。测试环境中使用：set global long_query_time = 0;、set global log_slow_extra = on;。

审计日志采集
分析和预警

怎么判断慢查询语句是否有优化空间?

对比执行过程的消耗，跟输出结果。如创建表并插入数据：

drop table if exists a;

create table a(id int primary key AUTO_INCREMENT, c int , d int,e text, index(c))engine=innodb;

DROP PROCEDURE IF EXISTS insert_data;

-- 创建存储过程
DELIMITER //
CREATE PROCEDURE insert_data()
BEGIN
    DECLARE i INT DEFAULT 1;
    WHILE i <= 100 DO
        INSERT INTO a ( c, d, e)
        SELECT  i, i, REPEAT('a', 16000);
        SET i = i + 1;
    END WHILE;
END //
DELIMITER ;

-- 调用存储过程来执行插入操作
CALL insert_data();

select * from a;

表本身很大，没有优化空间
select * from a where c>10 and c<20 and d>=15;

读了9行，但是只返回了5行。

# User@Host: root[root] @ localhost []  Id:    34
# Query_time: 0.000679  Lock_time: 0.000006 Rows_sent: 5  Rows_examined: 9
SET timestamp=1737638707;
select * from a where c>10 and c<20 and d>=15;

优化语句：

select * from a where id in (select id from a where c>10 and c<20 and d>=15);

慢查询日志：

# Time: 2025-01-23T13:25:41.458971Z
# User@Host: root[root] @ localhost []  Id:    34
# Query_time: 0.000880  Lock_time: 0.000004 Rows_sent: 5  Rows_examined: 14
SET timestamp=1737638741;
select * from a where id in (select id from a where c>10 and c<20 and d>=15);

理论分析，因为e字段笔记大，这里用到了mysql的行外存储(https://www.cnblogs.com/better-farther-world2099/articles/14717436.html)，所以第一个语句返回的是9行完整的数据行，再进行d字段的过滤。而第二个语句返回的是9个不完整的的数据行，然后再回表获取5个完整的数据行。

测试结果与实际测试结果不一致，应该是当前数据行的大小还不够大。理论分析是成立的。建立c和d的联合索引应该是更好的，存储层只会给sql层返回5行完整数据。

课堂练习

题目1

RR隔离级别下，表t的建表结构和初始化数据如下:

create table t(id int primary key,c int)engine=innodb;
insert into t values(1,1),(11,11),(21,21);

在会话1 执行如下语句:

begin;
select * from t lock in share mode;

那么，会话2的以下哪些语句会被进入“等待行锁”的状态?

A: insert into t values(15,15);

B: update t set c=c+1 where id=15;

C: delete from t where id=15;

D: alter table t add d int;

A

A会被锁住，RR隔离级别要保证可重复读，会加间隙锁

B、C不会，没有相关行，不会锁任何行

D也不会，因为D需要的是表结构锁。

题目2

表t1使用InnoDB引擎，以下哪个场景会导致语句Q1: select * from t1 limit 1 被堵住?

A:另一个线程在Q1执行之前，执行了 alter table t1 add index(f1)，当前处于“拷贝数据到临时表”阶段

B:另一个线程在Q1执行之前，执行了 truncate table t1,当前处于waiting for metadata lock阶段

C:另一个线程在Q1执行之前，执行了 delete from t1，且未执行完成

D:另一个线程在Q1执行之前，执行了 lock table t1 write，并执行完成

A：Mysql实现在线加索引

B：

MDL机制简介

MDL是 MySQL 为了保证数据定义语言（DDL）和数据操纵语言（DML）操作之间的数据一致性而引入的一种锁机制。当一个事务对表执行 DDL 操作（如 TRUNCATE TABLE）时，会获取该表的元数据写锁；而当执行DML操作（如SELECT）时，会获取该表的元数据读锁。

具体阻塞原因

TRUNCATE TABLE 操作：TRUNCATE TABLE 是一个 DDL 操作，执行时会获取表 t1 的元数据写锁。元数据写锁是排他锁，意味着在持有该锁期间，其他事务无法获取该表的任何元数据锁（包括读锁和写锁）。
SELECT 操作：SELECT * FROM t1 LIMIT 1 是一个 DML 操作，执行时需要获取表 t1 的元数据读锁。但由于之前的 TRUNCATE TABLE 操作已经持有了元数据写锁，所以 SELECT 操作无法获取到元数据读锁，只能进入等待状态，即 waiting for metadata lock。

C：不影响Q1的第一行数据的读取

D：也会阻塞，因为加的是表的排他锁。