pt-query-digest（percona toolkit）小解

pt-query-digest可以通過logs, processlist, 和tcpdump來分析MySQL的查詢相關信息，基本語法如下： pt-query-digest [OPTIONS] [FILES] [DSN] pt-query-digest是一種用於分析MySQL查詢的簡單易用的工具，沒有 ...

pt-query-digest可以通過logs, processlist, 和tcpdump來分析MySQL的查詢相關信息，基本語法如下：

pt-query-digest [OPTIONS] [FILES] [DSN]

pt-query-digest是一種用於分析MySQL查詢的簡單易用的工具，沒有之一。它可以分析MySQL慢日誌，general LOG和二進位日誌的查詢。（二進位日誌必須首先轉換為文本，通過mysqlbinlog工具）。它也可以使用SHOW PROCESSLIST和來自tcpdump的MySQL協議數據。預設情況下，該工具報告哪個查詢最慢，因此最重要的是進行優化。可以通過使用--group-by，--filter和--embedded-attributes等參數來創建更自定義的報告。 pt-query-digest主要有以下幾個功能： (1)使用slow.log來生成統計信息：

pt-query-digest slow.log

(2)從processlist的方式分析生成報告：

pt-query-digest --processlist h=host1

(3)通過tcppdump抓包分析慢查詢：

tcpdump -s 65535 -x -nn -q -tttt -i any -c 1000 port 3306 > mysql.tcp.txt
pt-query-digest --type tcpdump mysql.tcp.txt

(4)將慢日誌查詢分析到另一臺主機：

pt-query-digest --review h=host2 --no-report slow.log

下麵看一下主要參數： --type 預設為slowlog，參數值可以設置為binlog，genlog,slowlog,tcpdump,rawlog等。 --processlist 通過processlist分析MySQL的滿日誌查詢 --create-review-table 當使用--review參數把分析結果輸出到表中時，如果沒有表就自動創建。 --create-history-table 當使用--history參數把分析結果輸出到表中時，如果沒有表就自動創建。 --filter 對輸入的慢查詢按指定的字元串進行匹配過濾後再進行分析 --limit限制輸出結果百分比或數量，預設值是20,即將最慢的20條語句輸出，如果是50%則按總響應時間占比從大到小排序，輸出到總和達到50%位置截止。 --host MySQL伺服器地址 --user mysql用戶名 --password mysql用戶密碼 --history 將分析結果保存到表中，分析結果比較詳細，下次再使用--history時，如果存在相同的語句，且查詢所在的時間區間和歷史表中的不同，則會記錄到數據表中，可以通過查詢同一CHECKSUM來比較某類型查詢的歷史變化。 --review 將分析結果保存到表中，這個分析只是對查詢條件進行參數化，一個類型的查詢一條記錄，比較簡單。當下次使用--review時，如果存在相同的語句分析，就不會記錄到數據表中。 --output 分析結果輸出類型，值可以是report(標準分析報告)、slowlog(Mysql slow log)、json、json-anon，一般使用report，以便於閱讀。 --since 從什麼時間開始分析，值為字元串，可以是指定的某個”yyyy-mm-dd [hh:mm:ss]”格式的時間點，也可以是簡單的一個時間值：s(秒)、h(小時)、m(分鐘)、d(天)，如12h就表示從12小時前開始統計。 --until 截止時間，配合—since可以分析一段時間內的慢查詢。下麵看一下預設的輸出報表相關的信息：（1）數據統計信息

# 2291.9s user time, 6.4s system time, 41.68M rss, 193.36M vsz
# Current date: Mon Jun 19 11:19:51 2017
# Hostname: mxqmongodb2
# Files: /home/mysql/db3306/log/slowlog_343306.log
# Overall: 6.72M total, 140 unique, 16.12 QPS, 0.69x concurrency _________
# Time range: 2017-06-13T14:34:41 to 2017-06-18T10:22:04
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 287519s 1us 20s 43ms 148ms 339ms 214us
# Lock time 151259s 0 20s 23ms 144us 319ms 47us
# Rows sent 5.40M 0 1000 0.84 0.99 6.58 0.99
# Rows examine 388.33M 0 3.72k 60.59 5.75 388.16 0.99
# Query size 692.26M 6 799 108.02 202.40 69.96 80.10

以上包含信息Hostname主機名，Overall總查詢，unique單獨查詢，分析時間段Time range， Attribute部分和第三部分是一樣的，放到最好分析（2）慢查詢SQL統計結果和開銷統計

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ================= ======= ====== ===== =========
# 1 0x255C57D761A899A9 146053.6926 50.8% 75972 1.9225 2.93 UPDATE warehouse
# 2 0x813031B8BBC3B329 94038.9621 32.7% 242741 0.3874 0.23 COMMIT
# 3 0xA0352AA54FDD5DF2 10125.5055 3.5% 75892 0.1334 0.43 UPDATE order_line
# 4 0xE5E8C12332AD11C5 5660.5113 2.0% 75977 0.0745 0.83 SELECT district
# 5 0xBD195A4F9D50914F 3634.6219 1.3% 757760 0.0048 1.01 SELECT stock
# 6 0xF078A9E73D7A8520 3431.3527 1.2% 75874 0.0452 0.81 UPDATE district
# 7 0x9577D48F480A1260 2307.4342 0.8% 50255 0.0459 1.25 SELECT customer
# 8 0xFFDA79BA14F0A223 2158.4731 0.8% 75977 0.0284 0.54 SELECT customer warehouse
# 9 0x5E61FF668A8E8456 1838.4440 0.6% 1507614 0.0012 0.74 SELECT stock
# 10 0x10BEBFE721A275F6 1671.8274 0.6% 757751 0.0022 0.52 INSERT order_line
# 11 0x8B2716B5B486F6AA 1658.5984 0.6% 75871 0.0219 0.75 INSERT history
# 12 0xBF40A4C7016F2BAE 1504.7939 0.5% 758569 0.0020 0.77 SELECT item
# 13 0x37AEB73B59EFC119 1470.5951 0.5% 2838 0.5182 0.27 INSERT SELECT tpcc._stock_new tpcc.stock
# 15 0x26C4F579BF19956D 1030.4416 0.4% 1982 0.5199 0.28 INSERT SELECT tpcc.__stock_new tpcc.stock
# 22 0xD80B7970DBF2419C 493.0831 0.2% 947 0.5207 0.28 INSERT SELECT tpcc.__stock_new tpcc.stock
# 23 0xDE7EA4E363CAD006 488.2134 0.2% 943 0.5177 0.25 INSERT SELECT tpcc.__stock_new tpcc.stock
# 25 0x985B012461683472 470.6418 0.2% 907 0.5189 0.25 INSERT SELECT tpcc.__stock_new tpcc.stock
# MISC 0xMISC 9482.0467 3.3% 2182254 0.0043 0.0 <123 ITEMS>

其中信息包含了Response: 總的響應時間，time: 該查詢在本次分析中總的時間占比。calls: 執行次數，即本次分析總共有多少條這種類型的查詢語句。R/Call: 平均每次執行的響應時間。Item : SQL操作表。（3）第三部分，每個SQL的詳細信息

# Query 1: 1.14 QPS, 2.19x concurrency, ID 0x255C57D761A899A9 at byte 1782619576
# This item is included in the report because it matches --limit.
# Scores: V/M = 2.93
# Time range: 2017-06-13T14:34:42 to 2017-06-14T09:05:56
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 1 75972
# Exec time 50 146054s 160us 20s 2s 7s 2s 1s
# Lock time 94 142872s 39us 20s 2s 7s 2s 992ms
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 0 74.19k 1 1 1 1 0 1
# Query size 0 4.05M 53 57 55.88 56.92 0.82 54.21
# String:
# Hosts 127.0.0.1
# Users root
# Query_time distribution
# 1us
# 10us
# 100us ######################
# 1ms ##
# 10ms ###
# 100ms ##################################
# 1s ################################################################
# 10s+ ##
# Tables
# SHOW TABLE STATUS LIKE 'warehouse'\G
# SHOW CREATE TABLE `warehouse`\G
UPDATE warehouse SET w_ytd = w_ytd + 3651 WHERE w_id = 4\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select w_ytd = w_ytd + 3651 from warehouse where w_id = 4\G

Query 1，就是按照開銷來說排名第一的查詢，第一行是表的列標題。百分比是整個分析運行的總和的百分比，total是指定指標的實際值。例如，在這種情況下，我們可以看到查詢執行了75972次，占文件中查詢總數的50％。 min，max和avg列是不言自明的。 95％的列顯示了第95個百分點;值的95％小於或等於該值。標準偏差顯示了數值是如何緊密分組的。標準偏差和中位數都是從第95個百分點計算出來的，捨棄極大值最小值。下麵我們看一下常規的用法： 1：分析慢日誌預設報表

[root@mxqmongodb2 bin]# ./pt-query-digest /home/mysql/db3306/log/slowlog_343306.log >/home/sa/slowlog_343306.log

按照時間來切分，一般情況我們會分析一天的慢日誌：

[root@mxqmongodb2 bin]# ./pt-query-digest --since=24h /home/mysql/db3306/log/slowlog_343306.log >/home/sa/slowlog_343306_24.log

而且我們可以設置過濾條天通過--filter參數，更好生成我們想要的報表。例如只查詢select：--filter '$event->{arg} =~ m/^select/i'，只查詢某個用戶：--filter '($event->{user} || "") =~ m/^dba/i' ，全表掃描等：--filter '(($event->{Full_scan} || "") eq "yes") ||(($event->{Full_join} || "") eq "yes")' 2：保存分析結果到表文件：

[root@mxqmongodb2 bin]# ./pt-query-digest --user=root --password=123456 --port=3306 --review h=172.16.16.35,D=test,t=query_report /home/mysql/db3306/log/slowlog_343306.log

看一下結果樣式

mysql> select * from query_report limit 1\G
*************************** 1. row ***************************
checksum: 1206612749604517366
fingerprint: insert into order_line (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_quantity, ol_amount, ol_dist_info) values(?+)
sample: INSERT INTO order_line (ol_o_id, ol_d_id, ol_w_id, ol_number, ol_i_id, ol_supply_w_id, ol_quantity, ol_amount, ol_dist_info) VALUES (3730, 6, 10, 1, 6657, 10, 8, 62.41910171508789, 'N3F5fAhga7U51tlXr8AEgZdi')
first_seen: 2017-06-13 14:34:42
last_seen: 2017-06-14 09:05:54
reviewed_by: NULL
reviewed_on: NULL
comments: NULL
1 row in set (0.00 sec)

3：分析binlog（要先使用mysqlbinlog將binlog轉換）

[root@mxqmongodb2 log]# mysqlbinlog mysql-bin.000012 >/home/sa/mysql-bin_000012.log
[root@mxqmongodb2 bin]# ./pt-query-digest --type=binlog /home/sa/mysql-bin_000012.log >/home/sa/mysql-bin_000012_report.log

這個測試的時候還是有點小迷茫的，因為列印的結果並不是我要的，難道是因為我的binlog格式是ROW？保留下來，後面在測試。 4：分析general log 加上--type=genlog 即可，沒有驗證。。。。。。 5：tcpdump抓包分析我們先要開啟壓力測試：

[root@mxqmongodb2 tpcc-mysql]# ./tpcc_start -h127.0.0.1 -P3306 -d tpcc -u root -p123456 -w 10 -c 10 -r 10 -l 3000

連續測試三十分鐘，提供我們的抓取數據：

[root@mxqmongodb2 log]# tcpdump -s 65535 -x -nn -q -tttt -i any -c 10000 port 3306 >/home/sa/mysql.tcp.txt
[root@mxqmongodb2 bin]# ./pt-query-digest --type=tcpdump /home/sa/mysql.tcp.txt >/home/sa/mysql.tcp_repot.txt

看一下效果：

[root@mxqmongodb2 sa]# cat mysql.tcp_repot.txt
 
# 4.2s user time, 50ms system time, 27.65M rss, 179.15M vsz
# Current date: Tue Jun 20 17:08:40 2017
# Hostname: mxqmongodb2
# Files: /home/sa/mysql.tcp.txt
# Overall: 155 total, 3 unique, 9.76 QPS, 4.52x concurrency ______________
# Time range: 2017-06-20 17:06:19.850032 to 17:06:35.731291
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 72s 63us 2s 463ms 1s 352ms 393ms
# Rows affecte 25 0 15 0.16 0.99 1.18 0
# Query size 956 6 30 6.17 5.75 1.85 5.75
# Warning coun 1 0 1 0.01 0 0.08 0
 
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== =========
# 1 0x813031B8BBC3B329 69.9077 97.4% 153 0.4569 0.25 COMMIT
# MISC 0xMISC 1.8904 2.6% 2 0.9452 0.0 <2 ITEMS>
 
# Query 1: 9.63 QPS, 4.40x concurrency, ID 0x813031B8BBC3B329 at byte 10100332
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.25
# Time range: 2017-06-20 17:06:19.850032 to 17:06:35.731291
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 98 153
# Exec time 97 70s 63us 2s 457ms 1s 336ms 393ms
# Rows affecte 100 25 0 15 0.16 0.99 1.19 0
# Query size 96 918 6 6 6 6 0 6
# Warning coun 100 1 0 1 0.01 0 0.08 0
# String:
# Hosts 127.0.0.1
# Query_time distribution
# 1us
# 10us #
# 100us ####
# 1ms #
# 10ms #
# 100ms ################################################################
# 1s ##########
# 10s+
commit\G