MySQL開啟慢查詢日誌並使用pt-query-digest 分析

MySQL · 發表 2019-03-09 11:20:47

摘要：慢查詢日誌會將查詢過程中超出你設定的時間的查詢記錄下來，以便供開發者進行分析和優化。 1. 開啟慢查詢 1.1 檢視當前設定 mysql> show variables like "%query%"; 輸出 +------------------...

慢查詢日誌會將查詢過程中超出你設定的時間的查詢記錄下來，以便供開發者進行分析和優化。

1. 開啟慢查詢

1.1 檢視當前設定

mysql> show variables like "%query%";

輸出

+------------------------------+-----------------------------------------+

| Variable_name | Value |

+------------------------------+-----------------------------------------+

| binlog_rows_query_log_events | OFF |

| ft_query_expansion_limit | 20 |

| have_query_cache | YES |

| long_query_time | 10.000000 |

| query_alloc_block_size | 8192 |

| query_cache_limit | 1048576 |

| query_cache_min_res_unit | 4096 |

| query_cache_size | 16777216 |

| query_cache_type | OFF |

| query_cache_wlock_invalidate | OFF |

| query_prealloc_size | 8192 |

| slow_query_log | OFF |

| slow_query_log_file | /var/lib/mysql/lgj-Lenovo-G470-slow.log |

+------------------------------+-----------------------------------------+

三個引數

slow_query_log ON/OFF ,使能開關
slow_query_log_file 慢查詢日誌目錄和檔名稱
long_query_time 超過該時間則進行記錄，5.1之前只設置到秒，5.1開始支援毫秒。

注意，開啟慢查詢會影響效能，因此應當在某一段時間內開啟，記錄一段時間後關閉掉。

1.2 配置

[email protected]:~/db-analysis$ whereis mysql

mysql: /usr/bin/mysql /usr/lib/mysql /etc/mysql /usr/local/mysql /usr/share/mysql /usr/share/man/man1/mysql.1.gz

我的配置檔案在/etc/mysql目錄下的my.cnf

配置

[mysqld]

port=3307

skip-grant-tables

!includedir /etc/mysql/conf.d/

!includedir /etc/mysql/mysql.conf.d/

#開啟慢查詢

slow_query_log = ON

#設定超時時間為0，也就是記錄所有的查詢

long_query_time = 0

設定完後儲存，重新啟動mysql

service mysql restart

重新檢視引數，已經更改。

mysql> show variables like "%query%";

+------------------------------+-----------------------------------------+

| Variable_name | Value |

+------------------------------+-----------------------------------------+

| binlog_rows_query_log_events | OFF |

| ft_query_expansion_limit | 20 |

| have_query_cache | YES |

| long_query_time | 0.000000 |

| query_alloc_block_size | 8192 |

| query_cache_limit | 1048576 |

| query_cache_min_res_unit | 4096 |

| query_cache_size | 16777216 |

| query_cache_type | OFF |

| query_cache_wlock_invalidate | OFF |

| query_prealloc_size | 8192 |

| slow_query_log | ON |

| slow_query_log_file | /var/lib/mysql/lgj-Lenovo-G470-slow.log |

+------------------------------+-----------------------------------------+

1.3 查詢

隨便執行一條查詢語句，然後檢視慢查詢日誌。

/usr/sbin/mysqld, Version: 5.7.25-0Ubuntu0.18.04.2 ((Ubuntu)). started with:

Tcp port: 3306 Unix socket: /var/run/mysqld/mysqld.sock

Time Id Command Argument

/usr/sbin/mysqld, Version: 5.7.25-0ubuntu0.18.04.2-log ((Ubuntu)). started with:

Tcp port: 3306 Unix socket: /var/run/mysqld/mysqld.sock

Time Id Command Argument

/usr/sbin/mysqld, Version: 5.7.25-0ubuntu0.18.04.2-log ((Ubuntu)). started with:

Tcp port: 3306 Unix socket: /var/run/mysqld/mysqld.sock

Time Id Command Argument

;

# Time: 2019-02-27T14:07:42.841770Z

# User@Host: skip-grants user[lgj] @ localhost [] Id: 2

# Query_time: 0.016232 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0

SET timestamp=1551276462;

;

# Time: 2019-02-27T14:07:51.774192Z

# User@Host: skip-grants user[lgj] @ localhost [] Id: 2

# Query_time: 0.000485 Lock_time: 0.000221 Rows_sent: 1 Rows_examined: 1

SET timestamp=1551276471;

select * from user;

# Time: 2019-02-27T14:07:55.839223Z

# User@Host: skip-grants user[lgj] @ localhost [] Id: 2

# Query_time: 0.000564 Lock_time: 0.000259 Rows_sent: 1 Rows_examined: 1

SET timestamp=1551276475;

# 查詢語句

select * from user;

# 記錄時間

# Time: 2019-02-27T14:08:07.404666Z

# User@Host: skip-grants user[lgj] @ localhost [] Id: 2

#查詢時間鎖表時間

# Query_time: 0.006318 Lock_time: 0.000435 Rows_sent: 13 Rows_examined: 1026

SET timestamp=1551276487;

從上面可以獲知查詢時間和鎖表時間，但是如果檔案比較大，查詢時間最長的查詢將會非常麻煩，需要使用相關的工具來進行分析。

2. qt-query-digest的使用

2.1 安裝

• 建立目錄： mkdir db-analysis && cd db-analysis

• 下載 pt-query-digest: curl -LO https://percona.com/get/pt-query-digest

• 設定執行許可權：chmod +x pt-query-digest

• 將慢查詢日誌的檔案複製到當前的目錄下

• 執行分析： ./pt-query-digest lgj-Lenovo-G470-slow.log

結果

# 220ms user time, 10ms system time, 33.67M rss, 90.27M vsz

# Current date: Wed Feb 27 22:55:05 2019

# Hostname: lgj-Lenovo-G470

# Files: lgj-Lenovo-G470-slow.log

# Overall: 9 total, 7 unique, 0.24 QPS, 0.00x concurrency ________________

# Time range: 2019-02-27T14:07:29 to 2019-02-27T14:08:07

# Attribute total min max avg 95% stddev median

# ============ ======= ======= ======= ======= ======= ======= =======

# Exec time 185ms 225us 122ms 21ms 122ms 37ms 6ms

# Lock time 2ms 0 485us 186us 467us 166us 159us

# Rows sent 50 0 13 5.56 12.54 5.25 0.99

# Rows examine 2.03k 0 1.00k 230.44 1012.63 419.72 0.99

# Query size 198 11 32 22 31.70 7.35 17.65

# Profile

# Rank Query ID Response time Calls R/Call V/M

# ==== ================================= ============= ===== ====== =====

# 1 0x751417D45B8E80EE5CBA2034458B... 0.1223 66.1% 1 0.1223 0.00 SHOW DATABASES

# 2 0xA11944C87A6A5C16FB38455BF703... 0.0320 17.3% 1 0.0320 0.00 SELECT

# 3 0x898255B1BE4F8C3044AE35A18286... 0.0155 8.4% 1 0.0155 0.00 ADMIN INIT DB

# 4 0xE77769C62EF669AA7DD5F6760F2D... 0.0134 7.3% 2 0.0067 0.00 SHOW VARIABLES

# MISC 0xMISC 0.0018 1.0% 4 0.0004 0.0 <3 ITEMS>

# Query 1: 0 QPS, 0x concurrency, ID 0x751417D45B8E80EE5CBA2034458B5BC9 at byte 1471

# This item is included in the report because it matches --limit.

# Scores: V/M = 0.00

# Time range: all events occurred at 2019-02-27T14:07:42

# Attribute pct total min max avg 95% stddev median

# ============ === ======= ======= ======= ======= ======= ======= =======

# Count 11 1

# Exec time 66 122ms 122ms 122ms 122ms 122ms 0 122ms

# Lock time 6 110us 110us 110us 110us 110us 0 110us

# Rows sent 20 10 10 10 10 10 0 10

# Rows examine 0 10 10 10 10 10 0 10

# Query size 7 14 14 14 14 14 0 14

# String:

# Databases microblog

# Hosts localhost

# Users skip-grants user

# Query_time distribution

# 1us

# 10us

# 100us

# 1ms

# 10ms

# 100ms ################################################################

# 1s

# 10s+

show databases\G

# Query 2: 0 QPS, 0x concurrency, ID 0xA11944C87A6A5C16FB38455BF7035609 at byte 1008

# This item is included in the report because it matches --limit.

# Scores: V/M = 0.00

# Time range: all events occurred at 2019-02-27T14:07:42

# Attribute pct total min max avg 95% stddev median

# ============ === ======= ======= ======= ======= ======= ======= =======

# Count 11 1

# Exec time 17 32ms 32ms 32ms 32ms 32ms 0 32ms

# Lock time 0 0 0 0 0 0 0 0

# Rows sent 2 1 1 1 1 1 0 1

# Rows examine 0 0 0 0 0 0 0 0

# Query size 8 17 17 17 17 17 0 17

# String:

# Hosts localhost

# Users skip-grants user

# Query_time distribution

# 1us

# 10us

# 100us

# 1ms

# 10ms ################################################################

# 100ms

# 1s

# 10s+

# EXPLAIN /*!50100 PARTITIONS*/

SELECT DATABASE()\G

# Query 3: 0 QPS, 0x concurrency, ID 0x898255B1BE4F8C3044AE35A182869033 at byte 1225

# This item is included in the report because it matches --limit.

# Scores: V/M = 0.00

# Time range: all events occurred at 2019-02-27T14:07:42

# Attribute pct total min max avg 95% stddev median

# ============ === ======= ======= ======= ======= ======= ======= =======

# Count 11 1

# Exec time 8 15ms 15ms 15ms 15ms 15ms 0 15ms

# Lock time 0 0 0 0 0 0 0 0

# Rows sent 0 0 0 0 0 0 0 0

# Rows examine 0 0 0 0 0 0 0 0

# Query size 15 30 30 30 30 30 0 30

# String:

# Databases microblog

# Hosts localhost

# Users skip-grants user

# Query_time distribution

# 1us

# 10us

# 100us

# 1ms

# 10ms ################################################################

# 100ms

# 1s

# 10s+

administrator command: Init DB\G

# Query 4: 0.05 QPS, 0.00x concurrency, ID 0xE77769C62EF669AA7DD5F6760F2D2EBB at byte 775

# This item is included in the report because it matches --limit.

# Scores: V/M = 0.00

# Time range: 2019-02-27T14:07:30 to 2019-02-27T14:08:07

# Attribute pct total min max avg 95% stddev median

# ============ === ======= ======= ======= ======= ======= ======= =======

# Count 22 2

# Exec time 7 13ms 6ms 7ms 7ms 7ms 559us 7ms

# Lock time 54 920us 435us 485us 460us 485us 35us 460us

# Rows sent 52 26 13 13 13 13 0 13

# Rows examine 98 2.00k 1.00k 1.00k 1.00k 1.00k 0 1.00k

# Query size 29 58 29 29 29 29 0 29

# String:

# Databases microblog

# Hosts localhost

# Users skip-grants user

# Query_time distribution

# 1us

# 10us

# 100us

# 1ms ################################################################

# 10ms

# 100ms

# 1s

# 10s+

show variables like "%query%"\G

Linux公社的RSS地址：https://www.linuxidc.com/rssFeed.aspx

本文永久更新連結地址：https://www.linuxidc.com/Linux/2019-03/157373.htm

MySQL開啟慢查詢日誌並使用pt-query-digest 分析

您可能也會喜歡…