《MYSQL 8 教學–DAY07–mysql-slow.log 快速彙整分析，使用 pt-query-digest》效能優化

本次的教學，主要分享MySQL在對資料表(Table)有了基本操作的相關知識後，後續維運時候常會遇到SQL Query撰寫不良導致資料庫滿載，標準做法是我們會到資料庫主機查找mysql-slow.log，不過因為資料過多，我們只想要把主要吃資源的Query前50筆做處置，不過這時候一筆一筆對似乎有點浪費時間，也容易漏看，這時候可以用個方便的工具pt-query-digest，他主要的功能是針對 MySQL 的 slow log 進行分析，最終給出彙整後的分析結果，讓你可以一目了然，針對有問題的SQL做優化與改進，號稱MySQL DBA維運必備神器，他能夠分析slow log 、 general log 、 binary log 等文件，本教學是以Mysql 8.0為出發的教學，當然一些通用語法Mysql 8.0之前的版本也適用喔，所以大家不用擔心，只要一起做，相信你也可以了解MySQL 的資料庫優化是怎麼一回事。

Table of Contents

設定mysql-slow.log

MySQL

$vim /etc/mysql/my.cnf

MariaDB

$vim /etc/mysql/mariadb.conf.d/50-server.cnf

參數設定

[mysqld]
# 開啟慢日誌功能
slow_query_log = 1
# 查詢時間超過 5 秒則定義為慢查詢（可自行調整秒數）
long_query_time = 5
# 將產生的 slow query log 放到你指定的地方
slow_query_log_file = /var/log/mysql/mysql-slow.log

重啟套用

#MySQL重啟指令
$systemctl restart mysql.service

#Mariadb重啟指令
$systemctl restart mariadb.service

驗證

#MySQL目前狀態指令
$systemctl status mysql.service

#Mariadb目前狀態指令
$systemctl status mariadb.service

登入MySQL驗證

#登入 MySQL
$ mysql -u root -p

#查詢相關設定參數是否套用
$ show variables like '%quer%';
+---------------------------------+---------------------------------+
| Variable_name                   | Value                           |
+---------------------------------+---------------------------------+
| expensive_subquery_limit        | 100                             |
| ft_query_expansion_limit        | 20                              |
| have_query_cache                | YES                             |
| log_queries_not_using_indexes   | OFF                             |
| long_query_time                 | 5.000000                        |
| query_alloc_block_size          | 16384                           |
| query_cache_limit               | 1048576                         |
| query_cache_min_res_unit        | 4096                            |
| query_cache_size                | 16777216                        |
| query_cache_strip_comments      | OFF                             |
| query_cache_type                | ON                              |
| query_cache_wlock_invalidate    | OFF                             |
| query_prealloc_size             | 24576                           |
| slow_query_log                  | ON                              |
| slow_query_log_file             | /var/log/mysql/mysql-slow.log   |
| wsrep_reject_queries            | NONE                            |
| wsrep_sst_donor_rejects_queries | OFF                             |
+---------------------------------+---------------------------------+

測試驗證

發生slow query後是否有被正確log下來

#登入mysql後執行以下指令
> SELECT SLEEP(6);
> exit;

$ cat /var/log/mysql/mysql-slow.log 

Time		    Id Command	Argument
# Time: 231013 10:14:14
# User@Host: root[root] @ 
# Thread_id: 58  Schema:   QC_hit: No
# Query_time: 6.000339  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0
# Rows_affected: 0  Bytes_sent: 63
SET timestamp=1697163254;
SELECT SLEEP(6);

#可以看到剛剛的slow query被正確的記錄了

安裝 pt-query-digest 分析工具

$ sudo apt-get install percona-toolkit

執行 pt-query-digest 分析工具

$ sudo pt-query-digest 需要分析的日誌.log > 分析完後輸出的結果.log

#例如
$ sudo pt-query-digest mysql-slow.log > 20231012-mysql-slow-results.log

分析結果說明

分析結果檔案中包含三部分資訊：整體統計，慢SQL統計彙總表，單一SQL的詳細資料

整體統計

# 630ms user time, 0 system time, 30.18M rss, 35.79M vsz
# Current date: Thu Oct 13 02:44:28 2023
# Hostname: rdpapa
# Files: mysql-slow20231012-0843.log
# Overall: 4.93k total, 67 unique, 0.60 QPS, 30.07x concurrency __________
# Time range: 2023-10-11T22:25:03 to 2023-10-13T00:42:53
# 屬性               總計      最小    最大    平均    95%  標準    中等
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time        248693s      5s    360s     50s    234s     73s     15s
# Lock time           115s       0      6s    23ms   925us   314ms    80us
# Rows sent          5.67M       0 120.96k   1.18k   28.75  10.83k       0
# Rows examine       1.24G   7.49k   1.09M 263.07k   1.03M 316.79k  68.96k
# Query size         2.22M      27   3.73k  472.22  487.09  317.58  463.90

慢SQL統計彙總表

# Profile
# 排名 查詢ID                         回應時間        呼叫次數
# Rank Query ID                      Response time     Calls R/Call  V/M  
# ==== ============================= ================= ===== ======= =====
#    1 0xDBA6CDFC8B8CF412753FA961... 236377.0700 95.0%  3731 63.3549 98.76 SELECT xxxx
#    2 0x90F64BE51CB57C565C249E0F...   1633.5559  0.7%   210  7.7788  0.56 SELECT xxxx
#    3 0x502B9610E16A7FA320D5D156...   1196.1309  0.5%    12 99.6776 29.16 SELECT xxxx
#    4 0xD766AB0614320800F2589571...   1186.3898  0.5%    92 12.8955  3.19 SELECT xxxx
#    5 0x95A5F9197CD5E7DE5C214CF7...    876.4440  0.4%    15 58.4296  4.82 SELECT xxxx
#    6 0x0130781DEDA4E707CA7EF13E...    819.5408  0.3%    98  8.3627  0.46 SELECT xxxx
#    7 0xC977A470D48E45335F68E57B...    802.7341  0.3%    15 53.5156  4.62 SELECT xxxx
#    8 0xB14CEB7E540C21B23C793ED9...    450.4372  0.2%    85  5.2993  0.01 SELECT xxxx
#    9 0xBB6D0D02B0D4D9B5517A561B...    400.8836  0.2%    40 10.0221  0.57 SELECT xxxx
#   10 0x23AB87A4C9C7307279C6E08A...    382.3739  0.2%    37 10.3344  0.97 SELECT xxxx
#   11 0x283976673BE9B14620373A9E...    367.3387  0.1%    59  6.2261  0.13 SELECT xxxx
#   12 0x9F691015262AB2B2258E6A15...    336.3738  0.1%    36  9.3437  0.77 SELECT xxxx
#   13 0x985842E2BA5662A1668F826F...    318.3723  0.1%    53  6.0070  0.12 SELECT xxxx
#   14 0x4DB4368DC45022C86D8F0C88...    295.6443  0.1%    48  6.1593  0.13 SELECT xxxx
#   16 0x08CB612AA7EE46BF6033405A...    278.9918  0.1%    25 11.1597  0.54 SELECT xxxx
#   17 0x3D34BFEDB15502E20DCAA15F...    270.0482  0.1%    34  7.9426  0.31 SELECT xxxx
#   18 0xF40A4D89B4138F0D0BC97AC8...    254.4974  0.1%    35  7.2714  0.27 SELECT xxxx
#   19 0xE6E65267762E90C91578F0D9...    228.2058  0.1%    22 10.3730  0.77 SELECT xxxx

單一SQL的詳細資料

# Query 1: 0.45 QPS, 28.58x concurrency, ID 0xDBA6CDFC8B8CF412753FA961E146FC36 at byte 2019293
# This item is included in the report because it matches --limit.
# Scores: V/M = 98.76
# Time range: 2023-10-11T22:25:03 to 2023-10-13T00:42:53
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         75    3731
# Exec time     95 236377s      5s    360s     63s    258s     79s     21s
# Lock time      2      2s    27us   316ms   635us   881us     7ms    73us
# Rows sent      0     506       0       6    0.14    0.99    0.70       0
# Rows examine  93   1.15G  14.74k   1.09M 324.36k   1.03M 341.23k 328.61k
# Query size    75   1.68M     472     473  472.85  463.90    0.00  463.90
# String:
# Databases    
# Hosts        
# Users        
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  #############
#  10s+  ################################################################
# Tables
# EXPLAIN /*!50100 PARTITIONS*/
# 查詢過久的SQL語句
select xxxx

✒RDPAPA Tip 1

通過pt-query-digest 日誌分析結果，我們可以看出前50大的slow query有哪些，那些SQL執行的次數比較多，依據這個結果可以做後續的分析及優化進而達到提升查詢效能。

✒RDPAPA Tip 2

針對比較慢的SQL：可以朝幾個方向優化 1.建立所有檔案 2.減少部必要的table join 3.資料表的反正規劃降低資料的複雜度

針對使用頻率較高的SQL：可以朝幾個方向優化 1.程式面Cache 2.MySQL Query Cache

Reference

RD爸爸

你好，我是RD爸，希望透過我的紀錄，可以帶給你一些新的想法～專注於各式3C產品的開箱評測、程式相關技術及理財筆記。

email ►[email protected]