SEO外包平台,我们为您提供专业的企业网站SEO整站优化外包服务 SEO设置

SEO外包平台

专注于企业网站SEO整站优化外包服务

mysql slow log慢日志精讲与profile工具分析原因

作者:jcmp      发布时间:2021-04-25      浏览量:0
一、前提:拿存储过程做实验模拟慢语句下面

一、前提:拿存储过程做实验模拟慢语句

下面的存储过程定义了向testlog表插入十万行记录,不显式开启一个事务放进存储过程,而直接执行存储过程,会被认为是存储过程内定义的十万次insert的DML操作,事务日志刷写级别innodb_flush_log_at_trx_commit无论是 0|1|2 都很慢,模拟慢语句,超过慢语句设置的阈值时间10S 达标。

(root@localhost) [hellodb]> delimiter //(root@localhost) [hellodb]> create procedure sp_testlog()begindeclare i int;set i=1;while i <= 100000do 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.sockTime 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: 0use 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-logReading mysql slow query log from slow-logCount: 2 Time=0.06s (0s) Lock=0.00s (0s) Rows=150000.0 (300000), root[root]@localhostselect * from testlogCount: 1 Time=24.52s (24s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@localhostcall sp_testlogDied 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-logReading mysql slow query log from slow-logCount: 1 Time=24.52s (24s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@localhost call sp_testlogCount: 2 Time=0.06s (0s) Lock=0.00s (0s) Rows=150000.0 (300000), root[root]@localhost select * from testlogDied at /usr/local/mysql/bin/mysqldumpslow line 162, <> chunk 3.

c. 使用profile工具 当我们通过慢日志记录慢语句有两种情况: 第一种:大于慢日志设置时间阈值。

第二种:不使用索引或使用全索引扫描,不论是否达到慢日志查询时间阈值 都会记录日志。默认 log_queries_not_using_indexes=0 不记录。

但是 我们通过上面介绍的mysqldumpslow工具分析出慢日志语句有哪些,通过执行计划只能看到该语句走没走索引 或者走索引了 走的是辅助索引还是主键索引,回表次数。不清楚具体执行阶段哪里慢。通过profile工具可以查询出语句执行具体步骤。

下面开始介绍profile工具的使用

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执行时间太长了。