slow-log
前提：拿存儲過程做實(shí)驗?zāi)M慢語句
下面的存儲過程定義了向testlog表插入十萬行記錄瞎疼，不顯式開啟一個事務(wù)放進(jìn)存儲過程导犹，而直接執(zhí)行存儲過程，會被認(rèn)為是存儲過程內(nèi)定義的十萬次insert的DML操作溺森，事務(wù)日志刷寫級別innodb_flush_log_at_trx_commit無論是 0|1|2 都很慢癞己，模擬慢語句，超過慢語句設(shè)置的閾值時間10S 達(dá)標(biāo)似将。
(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.查看事務(wù)日志刷寫級別和慢日志閾值時間
(root@localhost) [hellodb]> select @@innodb_flush_log_at_trx_commit;
+----------------------------------+
| @@innodb_flush_log_at_trx_commit |
+----------------------------------+
| 2 |
+----------------------------------+
1 row in set (0.01 sec)
#即便此時事務(wù)日志刷寫級別是2 但是存儲過程定義的十萬條DML語句被認(rèn)為十萬次事務(wù)获黔，2級別每次事務(wù)提交后不會立即刷寫到磁盤 而是將已提交的事務(wù)從log-buffer放到os-buffer中，每秒執(zhí)行一次os-buffer內(nèi)所有事務(wù)的落盤操作在验。
(root@localhost) [hellodb]> select @@long_query_time;
+-------------------+
| @@long_query_time |
+-------------------+
| 10.000000 |
+-------------------+
1 row in set (0.00 sec)
#閾值是十秒 夠了
2.執(zhí)行存儲過程
執(zhí)行存儲過程 模擬慢語句 此時該語句會被記錄在慢日志中
(root@localhost) [hellodb]> call sp_testlog;
Query OK, 1 row affected (31.81 sec)
#我們看到該語句執(zhí)行時間31秒 慢日志當(dāng)然也是31秒 生產(chǎn)中都是代碼生成的查詢語句 我們不可能交互式看時間玷氏。而是從日志看慢語句
(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的慢語句執(zhí)行時間31S Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
use hellodb;
SET timestamp=1610807336;
call sp_testlog; #這個是超過閾值的慢語句
b. mysqldumpslow分析日志文件
這兩個例子里面我因為設(shè)置了不走索引的語句記錄慢日志，所以select. * from testlog即使時間沒有超過閾值10S 也會被記錄下
b.1 以慢查詢語句出現(xiàn)的次數(shù)排序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工具
當(dāng)我們通過慢日志記錄慢語句有兩種情況：
第一種：大于慢日志設(shè)置時間閾值
(root@localhost) [(none)]> select @@long_query_time;
+-------------------+
| @@long_query_time |
+-------------------+
| 10.000000 |
+-------------------+
1 row in set (0.00 sec)
第二種：不使用索引或使用全索引掃描腋舌，不論是否達(dá)到慢日志查詢時間閾值 都會記錄日志盏触。默認(rèn)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工具分析出慢日志語句有哪些，通過執(zhí)行計劃只能看到該語句走沒走索引 或者走索引了 走的是輔助索引還是主鍵索引，回表次數(shù)赞辩。不清楚具體執(zhí)行階段哪里慢雌芽。通過profile工具可以查詢出語句執(zhí)行具體步驟
下面開始介紹profile工具的使用
profile工具
profiling只是系統(tǒng)變量 不是命令選項和配置選項。所以只能系統(tǒng)內(nèi)部
set profiling使用c.1 使用流程
(root@localhost) [hellodb]> show variables like '%profi%';
+------------------------+
-------+
| Variable_name | Value |
+------------------------+-------+
| have_profiling | YES |
| profiling | OFF |
| profiling_history_size | 15 |
+------------------------+-------+
#打開后诗宣，會顯示語句執(zhí)行詳細(xì)的過程
set profiling = ON
#查看語句,注意結(jié)果中的query_id值
show profiles
#顯示語句的詳細(xì)執(zhí)行步驟和時長
Show profile for query N # N為show profiles查詢出來的query_ID
#profile工具歷史記錄15條
set profiling_history_size=15
c.2 制造慢語句 使用profile工具查詢?yōu)樯堵?/strong>
(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 函數(shù)休息了一秒 | 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函數(shù)休息了一秒膘怕，此時可以診斷出問題了
(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執(zhí)行時間太長了
