MySQL慢查詢日志釋疑總結


 

之前寫了一篇MySQL慢查詢日志總結,總結了一些MySQL慢查詢日志常用的相關知識,這里總結一下在工作當中遇到關於MySQL慢查詢日志的相關細節問題,有些是釋疑或自己有疑惑,自己測試驗證、解惑方面的知識。此篇只是總結個人的一些經驗,不足之處,敬請指正!

 

 

 

1: 為什么在慢查詢日志里面出現Query_time小於long_query_time閥值的SQL語句呢?

 

 

例如,如下截圖,long_query_time=5, 但是Query_time小於1秒的SQL都記錄到慢查詢日志當中了。

 

clip_image001

 

 

相信有些人遇到這個問題的時候覺得很奇怪,其實這個不是bug,而是你設置了系統變量log_queries_not_using_indexes ,這個系統變量開啟后,

會將那些未使用索引的SQL也被記錄到慢查詢日志中,另外,full index scan的SQL也會被記錄到慢查詢日志。所以,當滿足這些條件的SQL,即

使Query_time時間小於long_query_time的值,也會被記錄到慢查詢日志。

 

 

 

2: 使用日志分析工具mysqldumpslow分析有些日志非常慢,如何加快?

 

 

mysqldumpslow -s t -t 10 /var/lib/mysql/MyDB-slow.log

 

1: 出現這種情況是因為慢查詢日志變得很大(個人遇到的案例,慢查詢日志就有2G多了),所以,需要每天或每周切分慢查詢日志。設置一個Crontab作業即可。

 

 /var/lib/mysql/DB-Server-slow.log.20181112

 /var/lib/mysql/DB-Server-slow.log.20181113

 /var/lib/mysql/DB-Server-slow.log.20181114

 /var/lib/mysql/DB-Server-slow.log.20181115

 

2: 開啟了系統變量log_queries_not_using_indexes后,如果系統設計糟糕,未使用索引的SQL很多,那么這一類的日志可能會有很多,所以還有個特別的開關log_throttle_queries_not_using_indexes用於限制每分鍾輸出未使用索引的日志數量。

 

 

 

3:mysqldumpslow的生成報告中的Count、 Time、 Lock、Rows代表具體意思。

 

 

mysqldumpslow -s c -t 10 /var/lib/mysql/MyDB-slow.log  使用mysqldumpslow分析慢查詢日志分析獲取訪問次數最多的10個SQL。

 

Count :        表示這個SQL總共執行了195674次(慢查詢日志中出現的次數)

Time            表示執行時間,后面括號里面的38s 表示這個SQL語句累計的執行耗費時間為38秒。其實就是單次執行的時間和總共執行消耗的時間的區別。

Lock            表示鎖定時間,后面括號里面表示這些SQL累計的鎖定時間為48s

Rows            表示返回的記錄數,括號里面表示所有SQL語句累計返回記錄數

 

 

clip_image002

 

 

然后我們看看慢查詢日志的相關信息:

 

 

clip_image003

 

 

# Time: 2018-11-15T01:43:51.338167Z    

 

這個表示日志記錄的時間,確切的說是SQL執行完的時間點。注意這個時間有可能跟系統當前時間不一致,它可能是UTC時間。這個要看系統變量log_timestamps是UTC還是system。 

mysql> show variables like 'log_timestamps';
+----------------+-------+
| Variable_name  | Value |
+----------------+-------+
| log_timestamps | UTC   |
+----------------+-------+
1 row in set (0.01 sec)
 
mysql> set global log_timestamps=system;
Query OK, 0 rows affected (0.00 sec)

 

# User@Host: xxx[xxx] @  [xxx.xxx.xxx.xxx]  Id: 23781

客戶端的賬戶信息,兩個用戶名(第一個是授權賬戶,第二個為登錄賬戶),客戶端IP地址,還有mysqld的線程ID。

# Query_time: 16.480118  Lock_time: 0.000239 Rows_sent: 1  Rows_examined: 348011

查詢執行的信息,包括查詢時長,鎖持有時長,返回客戶端的行數,優化器掃描行數。通常需要優化的就是最后一個內容,盡量減少SQL語句掃描的數據行數

 

#use xxx;

#SET timestamp=1542246231;

 

這個是時間戳,你可以將其轉換為時間格式(注意時區),如下所示:

 

[root@mylnx02 ~]# date -d @1542246231

Thu Nov 15 09:43:51 CST 2018

 

[root@DB-Server ~]# date -d @1542246231

Wed Nov 14 20:43:51 EST 2018

 

 

 

 

4: 如何分析慢查詢日志一段時間內的數據呢?

 

 

mysqldumpslow這款工具沒有提供相關參數分析某個日期范圍內的慢查詢日志,也就是說沒法提供精細的搜索、分析。如果要分析某段時間內的慢查詢日志可以使用工具pt-query-digest 

 

如果實在需要使用mysqldumpslow分析某段時間內的慢查詢SQL,可以借助awk命令的幫助。如下樣例所示

 

 

#取出一天時間的慢查詢日志

# awk '/# Time: 2018-11-14/,/# Time: 2018-11-15/' DB-Server-slow.log > DB-Server-slow.log.20181114

 

 

#取出2018-11-14號4點到6點之間兩個小時的數據

#awk '/# Time: 2018-11-14T04/,/# Time: 2018-11-14T06/' DB-Server-slow.log > slow_04_06.log

 

 

5: 關於慢查詢日志中query_time和lock_time的關系。

 

 

只有當一個SQL的執行時間(不包括鎖等待的時間 lock_time)>long_query_time的時候,才會判定為慢查詢SQL;但是判定為慢查詢SQL之后,輸出的Query_time包括了(執行時間+鎖等待時間),並且也會輸出Lock_time時間。當一個SQL的執行時間(排除lock_time)小於long_query_time的時候(即使他鎖等待超過了很久),也不會記錄到慢查詢日志當中的。

 

 

 

6:  mysqldumpslow相關參數的詳細信息

 

#  mysqldumpslow --help
Usage: mysqldumpslow [ OPTS... ] [ LOGS... ]
 
Parse and summarize the MySQL slow query log. Options are
 
  --verbose    verbose  #顯示詳細信息
  --debug      debug    #調試模式下運行。
  --help       write this text to standard output
 
  -v           verbose #顯示詳細信息
  -d           debug   #調試模式下運行。
  -s ORDER     what to sort by (al, at, ar, c, l, r, t), 'at' is default  排序方式,at是默認方式
                al: average lock time  #平均鎖定時間排序
                ar: average rows sent  #平均發送行數排序
 
                at: average query time #平均查詢時間排序
 
                 c: count              #執行次數排序
 
                 l: lock time          #鎖定時間排序
 
                 r: rows sent          #總結果行數排序
 
                 t: query time         #總查詢時間排序
  -r           reverse the sort order (largest last instead of first) 
               #倒序信息排序
  -t NUM       just show the top n queries  
               #只顯示前n個查詢
  -a           don't abstract all numbers to N and strings to 'S'
  -n NUM       abstract numbers with at least n digits within names
  -g PATTERN   grep: only consider stmts that include this string
               #根據字符串篩選慢查詢日志
  -h HOSTNAME  hostname of db server for *-slow.log filename (can be wildcard),
               default is '*', i.e. match all
               #根據服務器名稱選擇慢查詢日志
  -i NAME      name of server instance (if using mysql.server startup script)
               #根據服務器MySQL實例名稱選擇慢查詢日志。
  -l           don't subtract lock time from total time  
               #不要從總時間減去鎖定時間

 

 

7:  系統變量Slow_queries會統計慢查詢出現的次數。

 

mysql>  show global status like '%slow%'; 
+---------------------+--------+
| Variable_name       | Value  |
+---------------------+--------+
| Slow_launch_threads | 0      |
| Slow_queries        | 120    |
+---------------------+--------+

 

 

8:系統變量slow_launch_time 是什么? 跟慢查詢日志有關系嗎?

 

   如果創建線程需要的時間比slow_launch_time多,服務器會增加Slow_launch_threads的狀態變量的數量。其實這個狀態變量跟慢查詢沒有什么關系。之所以放到這里,是有人問過這個問題!

 

 

 

 

 

參考資料:

 

https://rj03hou.github.io/mysql/MySQL%E6%85%A2%E6%9F%A5%E8%AF%A2%E6%97%B6%E9%97%B4%E5%88%86%E6%9E%90/

 

 


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM