SQL排查 - 慢查询日志 + 海量数据模拟分析

2022-01-26 03:54:44

慢查询日志

慢查询日志： MySQL提供的一种日志记录，用于记录MySQL中响应时间超过阈值的SQL语句(long_query_time, 默认10秒)

慢查询日志默认是关闭的；建议：开发调优时：打开，上线部署时：关闭

检查是否开启了慢查询日志

mysql> SHOW VARIABLES LIKE ‘%slow_query_log‘;
+----------------+-------+
| Variable_name  | Value |
+----------------+-------+
| slow_query_log | OFF   |
+----------------+-------+
1 row in set (0.00 sec)

慢查询日志两种开启方法临时开启 & 永久开启

-- ??慢查询日志临时开启(在内存中开启)
mysql> SET GLOBAL slow_query_log = 1;
Query OK, 0 rows affected (0.25 sec)

mysql> SHOW VARIABLES LIKE "%slow_query_log";
+----------------+-------+
| Variable_name  | Value |
+----------------+-------+
| slow_query_log | ON    |
+----------------+-------+
1 row in set (0.00 sec)

-- ??慢查询日志永久开启
/etc/my.cnf 中追加配置：
vi /etc/my.cnf 
[mysqld]
slow_query_log=1
slow_query_log_file=/var/lib/mysql/localhost-slow.log

慢查询阈值

mysql> SHOW VARIABLES LIKE "%long_query_time%";
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.03 sec)

慢查询阈值的设定临时设定 & 永久设定


-- ?? 临时设定慢查询日志中响应时间阈值
mysql> SET GLOBAL long_query_time = 5;
Query OK, 0 rows affected (0.00 sec)

-- 设置完毕后需要重新登录后(mysql -u root -p)才能生效（不需要重启MySQL服务)

mysql> SHOW VARIABLES LIKE "%long_query_time%";
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 5.000000 |
+-----------------+----------+
1 row in set (0.00 sec)

-- ?? 永久设定慢查询日志中响应时间阈值
/etc/my.cnf 中追加配置：
vi /etc/my.cnf 
[mysqld]
long_query_time=3

查看当前超过阈值的SQL

如果阈值long_query_time = 5，则凡是一个SQL语句响应时间 >= 5则被慢查询日志记录在案

mysql> SELECT SLEEP(4);
mysql> SELECT SLEEP(5);   -- 第一次超过
mysql> SELECT SLEEP(3);
mysql> SELECT SLEEP(3);
mysql> SELECT SLEEP(5);   -- 第二次超过
mysql> SELECT SLEEP(6);   -- 第三次超过

mysql> SHOW GLOBAL STATUS LIKE "%slow_queries%";
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Slow_queries  | 3     |
+---------------+-------+
1 row in set (0.00 sec)

通过慢查询日志查看具体的慢SQL

(1) 慢查询的SQL被记录在日志中，因此可以通过日志查看具体的慢SQL

cat /var/lib/mysql/localhost_slow.log##

(2) 通过myqsldumpslow工具查看慢SQL，可以通过一些过滤条件快速查找需要定位的慢SQL

mysqldumpslow -- help
s: 排序方式
r: 逆序
l: 锁定时间
g: 正则匹配模式

	--获取返回记录最多的3个SQL
		mysqldumpslow -s r -t 3  /var/lib/mysql/localhost-slow.log

	--获取访问次数最多的3个SQL
		mysqldumpslow -s c -t 3 /var/lib/mysql/localhost-slow.log

	--按照时间排序，前10条包含left join查询语句的SQL
		mysqldumpslow -s t -t 10 -g "left join" /var/lib/mysql/localhost-slow.log
	
	语法：
		mysqldumpslow 各种参数  慢查询日志的文件

-- 这是个人主机一个查看慢查询日志的例子
[root@openmind /]# cat /var/lib/mysql/openmind-slow.log
/usr/sbin/mysqld, Version: 5.5.60-log (MySQL Community Server (GPL)). started with:
Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sock
Time                 Id Command    Argument
# Time: 210627 12:39:28
# User@Host: root[root] @ localhost []
# Query_time: 5.001925  Lock_time: 0.00T timestamp=1624768768;
SELECT SLEEP(5);0000 Rows_sent: 1  Rows_examined: 0
SE
# Time: 210627 12:40:47
# User@Host: root[root] @ localhost []
# Query_time: 5.003010  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1624768847;
SELECT SLEEP(5);
# Time: 210627 12:41:31
# User@Host: root[root] @ localhost []
# Query_time: 6.002899  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1624768891;
SELECT SLEEP(6);

海量数据模拟分析

生成模拟的海量数据

模拟海量数据存储过程（无return）/存储函数（有return）

create database testdata ;
use testdata
create table dept
(
dno int(5) primary key default 0,
dname varchar(20) not null default ‘‘,
loc varchar(30) default ‘‘
)engine=innodb default charset=utf8;

create table emp
(
eid int(5) primary key,
ename varchar(20) not null default ‘‘,
job varchar(20) not null default ‘‘,
deptno int(5) not null default 0
)engine=innodb default charset=utf8;
+--------------------+
| Tables_in_testdata |
+--------------------+
| dept               |
| emp                |
+--------------------+

通过存储函数插入海量数据

创建存储函数：
		randstring(6)  ->aXiayx  用于模拟员工名称


	delimiter $ 
	create function randstring(n int)   returns varchar(255) 
	begin
		declare  all_str varchar(100) default ‘abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ‘ ;
		declare return_str varchar(255) default ‘‘ ;
		declare i int default 0 ; 
		while i<n		 
		do									
			set return_str = concat(  return_str,      substring(all_str,   FLOOR(1+rand()*52)   ,1)       );
			set i=i+1 ;
		end while ;
		return return_str;
		
	end $

--如果报错：You have an error in your SQL syntax，说明SQL语句语法有错，需要修改SQL语句；

 如果报错This function has none of DETERMINISTIC, NO SQL, or READS SQL DATA in its declaration and binary logging is enabled (you *might* want to use the less safe log_bin_trust_function_creators variable)
	是因为 存储过程/存储函数在创建时 与之前的 开启慢查询日志冲突了 
	解决冲突：
	临时解决( 开启log_bin_trust_function_creators )
		show variables like ‘%log_bin_trust_function_creators%‘;
		set global log_bin_trust_function_creators = 1;
	永久解决：
	/etc/my.cnf 
	[mysqld]
	log_bin_trust_function_creators = 1

--产生随机整数
	create function ran_num() returns int(5)
	begin
		declare i int default 0;
		set i =floor( rand()*100 ) ;
		return i ;

	end $
	


	--通过存储过程插入海量数据：emp表中  ，  10000,   100000
	create procedure insert_emp( in eid_start int(10),in data_times int(10))
	begin 
		declare i int default 0;
		set autocommit = 0 ;
		
		repeat
			
			insert into emp values(eid_start + i, randstring(5) ,‘other‘ ,ran_num()) ;
			set i=i+1 ;
			until i=data_times
		end repeat ;
		commit ;
	end $


	--通过存储过程插入海量数据：dept表中  
		create procedure insert_dept(in dno_start int(10) ,in data_times int(10))
		begin
			declare i int default 0;
			set autocommit = 0 ;
			repeat
			
				insert into dept values(dno_start+i ,randstring(6),randstring(8)) ;
				set i=i+1 ;
				until i=data_times
			end repeat ;
		commit ;
			

		end$


	--插入数据
		delimiter ; 
		call insert_emp(1000,800000) ;
		call insert_dept(10,30) ;

??分析海量数据

1. profiles - 笼统分析SQL

show profiles; -- 默认关闭
mysql> show variables like "%profiling%";
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| have_profiling         | YES   |
| profiling              | OFF   |
| profiling_history_size | 15    |
+------------------------+-------+
3 rows in set (0.00 sec)
mysql> SHOW VARIABLES LIKE "%profiling%";
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| have_profiling         | YES   |
| profiling              | OFF   |
| profiling_history_size | 15    |
+------------------------+-------+
3 rows in set (0.00 sec)

mysql> set profiling = on;  -- ??开启profiling
Query OK, 0 rows affected (0.00 sec)

mysql> SHOW VARIABLES LIKE "%profiling%";
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| have_profiling         | YES   |
| profiling              | ON    |
| profiling_history_size | 15    |
+------------------------+-------+
3 rows in set (0.00 sec)

mysql> show profiles; -- ??剖析数据，会记录所有profiling打开之后的全部SQL查询所花费的时间。缺点：不够精确，只能看到总共消费的时间，无法看到各个硬件消费的时间(cpu、io ...)
+----------+------------+-----------------------------------+
| Query_ID | Duration   | Query                             |
+----------+------------+-----------------------------------+
|        1 | 0.00523100 | SHOW VARIABLES LIKE "%profiling%" |
+----------+------------+-----------------------------------+
1 row in set (0.00 sec)

2. 精确分析：SQL诊断

show profile all for query [上一步查询的的Query_Id]
show profile cpu,block io for query [上一步查询的的Query_Id]

mysql> show profiles;
+----------+------------+-----------------------------------+
| Query_ID | Duration   | Query                             |
+----------+------------+-----------------------------------+
|        1 | 0.00523100 | SHOW VARIABLES LIKE "%profiling%" |
|        2 | 0.00007375 | SHOW profile ALL FOR query        |
|        3 | 0.00004850 | show profile all for query        |
+----------+------------+-----------------------------------+
3 rows in set (0.00 sec)


mysql> show profile all for query 1; \G   -- ??对指定的SQL语句进行分析
+--------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+---------------+-------------+
| Status             | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function       | Source_file   | Source_line |
+--------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+---------------+-------------+
| starting           | 0.000055 | 0.000033 |   0.000007 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | NULL                  | NULL          |        NULL |
| Opening tables     | 0.000024 | 0.000019 |   0.000005 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | open_tables           | sql_base.cc   |        4896 |
| System lock        | 0.000006 | 0.000005 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_lock_tables     | lock.cc       |         299 |
| init               | 0.000006 | 0.000005 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_select          | sql_select.cc |        2594 |
| optimizing         | 0.000002 | 0.000002 |   0.000000 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | optimize              | sql_select.cc |         865 |
| statistics         | 0.000005 | 0.000003 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | optimize              | sql_select.cc |        1071 |
| preparing          | 0.000005 | 0.000005 |   0.000001 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | optimize              | sql_select.cc |        1093 |
| executing          | 0.000141 | 0.000116 |   0.000026 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | exec                  | sql_select.cc |        1851 |
| Sending data       | 0.000013 | 0.000009 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | exec                  | sql_select.cc |        2395 |
| end                | 0.004932 | 0.000000 |   0.004120 |                 0 |                   1 |         4712 |             0 |             0 |                 0 |                 1 |                 0 |     0 | mysql_select          | sql_select.cc |        2630 |
| query end          | 0.000009 | 0.000000 |   0.000005 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command | sql_parse.cc  |        4516 |
| closing tables     | 0.000002 | 0.000000 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command | sql_parse.cc  |        4568 |
| removing tmp table | 0.000007 | 0.000000 |   0.000007 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | free_tmp_table        | sql_select.cc |       11305 |
| closing tables     | 0.000004 | 0.000000 |   0.000003 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | free_tmp_table        | sql_select.cc |       11330 |
| freeing items      | 0.000017 | 0.000000 |   0.000018 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_parse           | sql_parse.cc  |        5844 |
| logging slow query | 0.000002 | 0.000000 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | log_slow_statement    | sql_parse.cc  |        1516 |
| cleaning up        | 0.000002 | 0.000000 |   0.000002 |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | dispatch_command      | sql_parse.cc  |        1472 |
+--------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+---------------+-------------+
17 rows in set (0.00 sec)

ERROR: 
No query specified

show query cpu,block io for query [Query_Id]

mysql> show profile cpu,block io for query 17;
+--------------------------------+----------+----------+------------+--------------+---------------+
| Status                         | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+--------------------------------+----------+----------+------------+--------------+---------------+
| starting                       | 0.000015 | 0.000006 |   0.000004 |            0 |             0 |
| Waiting for query cache lock   | 0.000002 | 0.000002 |   0.000001 |            0 |             0 |
| checking query cache for query | 0.000024 | 0.000014 |   0.000010 |            0 |             0 |
| checking permissions           | 0.000051 | 0.000052 |   0.000000 |            0 |             0 |
| Opening tables                 | 0.000011 | 0.000010 |   0.000000 |            0 |             0 |
| System lock                    | 0.000007 | 0.000007 |   0.000000 |            0 |             0 |
| Waiting for query cache lock   | 0.000011 | 0.000012 |   0.000000 |            0 |             0 |
| init                           | 0.000008 | 0.000007 |   0.000000 |            0 |             0 |
| optimizing                     | 0.000004 | 0.000004 |   0.000000 |            0 |             0 |
| statistics                     | 0.000006 | 0.000006 |   0.000000 |            0 |             0 |
| preparing                      | 0.000005 | 0.000005 |   0.000000 |            0 |             0 |
| executing                      | 0.000003 | 0.000003 |   0.000000 |            0 |             0 |
| Sending data                   | 0.007180 | 0.006978 |   0.000000 |            0 |             0 |
| end                            | 0.000014 | 0.000009 |   0.000000 |            0 |             0 |
| query end                      | 0.000010 | 0.000010 |   0.000000 |            0 |             0 |
| closing tables                 | 0.000005 | 0.000005 |   0.000000 |            0 |             0 |
| freeing items                  | 0.000007 | 0.000007 |   0.000000 |            0 |             0 |
| Waiting for query cache lock   | 0.000004 | 0.000004 |   0.000000 |            0 |             0 |
| freeing items                  | 0.000014 | 0.000013 |   0.000000 |            0 |             0 |
| Waiting for query cache lock   | 0.000002 | 0.000002 |   0.000000 |            0 |             0 |
| freeing items                  | 0.000001 | 0.000001 |   0.000000 |            0 |             0 |
| storing result in query cache  | 0.000002 | 0.000002 |   0.000000 |            0 |             0 |
| logging slow query             | 0.000002 | 0.000001 |   0.000000 |            0 |             0 |
| cleaning up                    | 0.000002 | 0.000002 |   0.000000 |            0 |             0 |
+--------------------------------+----------+----------+------------+--------------+---------------+
24 rows in set (0.00 sec)

全局查询日志：记录开启之后的全部SQL语句。（这种全局的记录操作，仅仅在调优、开发过程中打开即可，在最终的部署时 ? 一定关闭）

		show variables like ‘%general_log%‘;
		
		--执行的所有SQL记录在表中
		set global general_log = 1 ;--开启全局日志
		set global log_output=‘table‘ ; --设置 将全部的SQL 记录在表中

		--执行的所有SQL记录在文件中
		set global log_output=‘file‘ ;
		set global general_log = on ;
		set global general_log_file=‘/tmp/general.log‘ ;
	
		开启后，会记录所有SQL ： 会被记录 mysql.general_log表中。
			select * from  mysql.general_log ;

SQL排查 - 慢查询日志 + 海量数据模拟分析

码农公寓

慢查询日志

检查是否开启了慢查询日志

慢查询阈值

查看当前超过阈值的SQL

通过慢查询日志查看具体的慢SQL

(1) 慢查询的SQL被记录在日志中，因此可以通过日志查看具体的慢SQL

(2) 通过myqsldumpslow工具查看慢SQL，可以通过一些过滤条件 快速查找需要定位的慢SQL

海量数据模拟分析

生成模拟的海量数据

通过存储函数 插入海量数据

??分析海量数据

1. profiles - 笼统分析SQL

2. 精确分析：SQL诊断

全局查询日志： 记录开启之后的全部SQL语句。（这种全局的记录操作，仅仅在调优、开发过程中打开即可，在最终的部署时 ? 一定关闭）

相关文章

(2) 通过myqsldumpslow工具查看慢SQL，可以通过一些过滤条件快速查找需要定位的慢SQL

通过存储函数插入海量数据

全局查询日志：记录开启之后的全部SQL语句。（这种全局的记录操作，仅仅在调优、开发过程中打开即可，在最终的部署时 ? 一定关闭）