slow-log
前提：拿存储过程做实验模拟慢语句
下面的存储过程定义了向testlog表插入十万行记录，不显式开启一个事务放进存储过程，而直接执行存储过程，会被认为是存储过程内定义的十万次insert的DML操作，事务日志刷写级别innodb_flush_log_at_trx_commit无论是 0|1|2 都很慢，模拟慢语句，超过慢语句设置的阈值时间10S 达标。
(root@localhost) [hellodb]> create table testlog(id int auto_increment primary key,name char(10),age int default 20);
Query OK, 0 rows affected (0.03 sec)
(root@localhost) [hellodb]> delimiter //
(root@localhost) [hellodb]> create procedure sp_testlog()
begin
declare i int;
set i=1;
while i <= 100000
do insert into testlog(name,age) values(concat("wang",i),i);
set i=i+1;
end while;
end//
Query OK, 0 rows affected (0.03 sec)
(root@localhost) [hellodb]> delimiter ;
1.查看事务日志刷写级别和慢日志阈值时间
(root@localhost) [hellodb]> select @@innodb_flush_log_at_trx_commit;
+----------------------------------+
| @@innodb_flush_log_at_trx_commit |
+----------------------------------+
| 2 |
+----------------------------------+
1 row in set (0.01 sec)
#即便此时事务日志刷写级别是2 但是存储过程定义的十万条DML语句被认为十万次事务，2级别每次事务提交后不会立即刷写到磁盘 而是将已提交的事务从log-buffer放到os-buffer中，每秒执行一次os-buffer内所有事务的落盘操作。
(root@localhost) [hellodb]> select @@long_query_time;
+-------------------+
| @@long_query_time |
+-------------------+
| 10.000000 |
+-------------------+
1 row in set (0.00 sec)
#阈值是十秒 够了
2.执行存储过程
执行存储过程 模拟慢语句 此时该语句会被记录在慢日志中
(root@localhost) [hellodb]> call sp_testlog;
Query OK, 1 row affected (31.81 sec)
#我们看到该语句执行时间31秒 慢日志当然也是31秒 生产中都是代码生成的查询语句 我们不可能交互式看时间。而是从日志看慢语句
(root@localhost) [hellodb]> select * from testlog;
3.分析慢日志
a.直接查看日志文件
root@17 log]# cat slow-log
/usr/local/mysql/bin/mysqld, Version: 8.0.19 (MySQL Community Server - GPL). started with:
Tcp port: 3306 Unix socket: /mysql/3306/sock/mysql.sock
Time Id Command Argument
# Time: 2021-01-16T14:28:56.102633Z
# User@Host: root[root] @ localhost [] Id: 8
# Query_time: 31.805307 #这里就是超过阈值10s的慢语句执行时间31S Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
use hellodb;
SET timestamp=1610807336;
call sp_testlog; #这个是超过阈值的慢语句
b. mysqldumpslow分析日志文件
这两个例子里面我因为设置了不走索引的语句记录慢日志，所以select. * from testlog即使时间没有超过阈值10S 也会被记录下
b.1 以慢查询语句出现的次数排序mysqldumpslow -s c -t 10 slow-log
root@17 log]# mysqldumpslow -s c -t 10 slow-log
Reading mysql slow query log from slow-log
Count: 2 Time=0.06s (0s) Lock=0.00s (0s) Rows=150000.0 (300000), root[root]@localhost
select * from testlog
Count: 1 Time=24.52s (24s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@localhost
call sp_testlog
Died at /usr/local/mysql/bin/mysqldumpslow line 162, <> chunk 3.
b.2 以慢查询语句的平均时间排序mysqldumpslow -s t -t 10 slow-log
root@17 log]# mysqldumpslow -s t -t 10 slow-log
Reading mysql slow query log from slow-log
Count: 1 Time=24.52s (24s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@localhost
call sp_testlog
Count: 2 Time=0.06s (0s) Lock=0.00s (0s) Rows=150000.0 (300000), root[root]@localhost
select * from testlog
Died at /usr/local/mysql/bin/mysqldumpslow line 162, <> chunk 3.
c. 使用profile工具
当我们通过慢日志记录慢语句有两种情况：
第一种：大于慢日志设置时间阈值
(root@localhost) [(none)]> select @@long_query_time;
+-------------------+
| @@long_query_time |
+-------------------+
| 10.000000 |
+-------------------+
1 row in set (0.00 sec)
第二种：不使用索引或使用全索引扫描，不论是否达到慢日志查询时间阈值 都会记录日志。默认log_queries_not_using_indexes=0不记录
(root@localhost) [(none)]> select @@log_queries_not_using_indexes;
+---------------------------------+
| @@log_queries_not_using_indexes |
+---------------------------------+
| 1 |
+---------------------------------+
1 row in set (0.00 sec)
但是 我们通过上面介绍的mysqldumpslow工具分析出慢日志语句有哪些，通过执行计划只能看到该语句走没走索引 或者走索引了 走的是辅助索引还是主键索引，回表次数。不清楚具体执行阶段哪里慢。通过profile工具可以查询出语句执行具体步骤
下面开始介绍profile工具的使用
profile工具
profiling只是系统变量 不是命令选项和配置选项。所以只能系统内部
set profiling使用c.1 使用流程
(root@localhost) [hellodb]> show variables like '%profi%';
+------------------------+
-------+
| Variable_name | Value |
+------------------------+-------+
| have_profiling | YES |
| profiling | OFF |
| profiling_history_size | 15 |
+------------------------+-------+
#打开后，会显示语句执行详细的过程
set profiling = ON
#查看语句,注意结果中的query_id值
show profiles
#显示语句的详细执行步骤和时长
Show profile for query N # N为show profiles查询出来的query_ID
#profile工具历史记录15条
set profiling_history_size=15
c.2 制造慢语句 使用profile工具查询为啥慢
(root@localhost) [hellodb]> set profiling = ON
(root@localhost) [hellodb]> select * from testlog where id>1000;
(root@localhost) [hellodb]> select sleep(1) from teachers;
+----------+
| sleep(1) |
+----------+
| 0 |
| 0 |
| 0 |
| 0 |
+----------+
4 rows in set (4.01 sec)
(root@localhost) [hellodb]> show profiles;
+----------+------------+-------------------------------------+
| Query_ID | Duration | Query |
+----------+------------+-------------------------------------+
| 1 | 0.10465625 | select * from testlog where id>1000 |
| 2 | 0.00019875 | show prifiling |
| 3 | 2.17644475 | select sleep(1) from teachers |
| 4 | 4.00434700 | select sleep(1) from teachers |
| 5 | 0.09275425 | select * from testlog where id>1000 |
+----------+------------+-------------------------------------+
5 rows in set, 1 warning (0.00 sec)
# 我们使用show profile for query 4 查询 第四条select sleep(1) from teachers 为啥这么慢
(root@localhost) [hellodb]> show profile for query 4;
+--------------------------------+----------+
| Status | Duration |
+--------------------------------+----------+
| starting | 0.000078 |
| Executing hook on transaction | 0.000005 |
| starting | 0.000008 |
| checking permissions | 0.000006 |
| Opening tables | 0.000027 |
| init | 0.000007 |
| System lock | 0.000008 |
| optimizing | 0.000004 |
| statistics | 0.000014 |
| preparing | 0.000013 |
| executing | 0.000027 |
| User sleep #sleep 函数休息了一秒 | 1.000131 |
| User sleep | 1.000784 |
| User sleep | 1.002001 |
| User sleep | 1.001088 |
| end | 0.000024 |
| query end | 0.000006 |
| waiting for handler commit | 0.000064 |
| closing tables | 0.000017 |
| freeing items | 0.000024 |
| cleaning up | 0.000013 |
+--------------------------------+----------+
21 rows in set, 1 warning (0.00 sec)
#查询得出原来中间用了四次sleep函数休息了一秒，此时可以诊断出问题了
(root@localhost) [hellodb]> show profiles;
+----------+------------+-----------------------+
| Query_ID | Duration | Query |
+----------+------------+-----------------------+
| 1 | 0.19421100 | select * from testlog |
+----------+------------+-----------------------+
1 row in set, 1 warning (0.00 sec)
(root@localhost) [hellodb]> show profile for query 1;
+--------------------------------+----------+
| Status | Duration |
+--------------------------------+----------+
| starting | 0.000302 |
| Executing hook on transaction | 0.000022 |
| starting | 0.000073 |
| checking permissions | 0.000022 |
| Opening tables | 0.000117 |
| init | 0.000018 |
| System lock | 0.000075 |
| optimizing | 0.000018 |
| statistics | 0.000084 |
| preparing | 0.000117 |
| executing | 0.193194 |
| end | 0.000025 |
| query end | 0.000006 |
| waiting for handler commit | 0.000012 |
| closing tables | 0.000013 |
| freeing items | 0.000012 |
| logging slow query | 0.000083 |
| cleaning up | 0.000022 |
+--------------------------------+----------+
18 rows in set, 1 warning (0.01 sec)
#这个就是纯属于select * from testlog没走索引 executing执行时间太长了
网友评论