pt-query-digest
[root@iz2ze6jo3o3bqbcongnyp ~]# pt-query-digest --since=1h /alidata1/mysql/data/slow.log > query.log
/alidata1/mysql/data/slow.log: 97% 00:00 remain
[root@iz2ze6jo3o3bqbcongnyp ~]# more query.log
# 30.6s user time, 1.8s system time, 27.76M rss, 222.10M vsz
# Current date: Sat Oct 6 20:01:11 2018
# Hostname: iz2ze6jo3o3bqbcongnyp
# Files: /alidata1/mysql/data/slow.log
# Overall: 924 total, 40 unique, 0.26 QPS, 0.45x concurrency _____________
# Time range: 2018-10-06T19:01:22 to 2018-10-06T20:00:10
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 1590s 190us 69s 2s 6s 7s 230ms
# Lock time 4s 31us 204ms 5ms 21ms 23ms 60us
# Rows sent 654.80k 0 23.48k 725.67 964.41 2.54k 6.98
# Rows examine 382.98M 0 23.66M 424.42k 683.15k 1.14M 312.96k
# Query size 347.89k 52 59.53k 385.54 592.07 1.88k 271.23
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== =============== ===== ======= ===== ============
# 1 0x088884A136067321 1343.1404 84.5% 59 22.7651 11.20
# 2 0x7726D867E0C35FB0 96.6822 6.1% 374 0.2585 0.00 SELECT customer_follower
# 3 0xDDF83730565F004F 56.5839 3.6% 2 28.2919 0.00 SELECT customer_operation_log
# 4 0x99F12C2EAC8D0E9F 37.1116 2.3% 27 1.3745 3.92 SELECT customer oms_customer_lidancount
# 5 0x03461C191C644E13 26.2014 1.6% 34 0.7706 1.90 SELECT callrecord
# MISC 0xMISC 29.9696 1.9% 428 0.0700 0.0 <35 ITEMS>
# Query 1: 0.02 QPS, 0.38x concurrency, ID 0x088884A136067321 at byte 479384240
# Scores: V/M = 11.20
# Time range: 2018-10-06T19:01:22 to 2018-10-06T20:00:09
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 6 59
# Exec time 84 1343s 92ms 69s 23s 45s 16s 23s
# Lock time 98 4s 2ms 204ms 70ms 189ms 60ms 49ms
# Rows sent 0 70 0 7 1.19 6.98 2.18 0
# Rows examine 0 2.26M 0 321.78k 39.31k 312.96k 100.97k 0.99
# Query size 0 3.46k 60 60 60 60 0 60
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms #
# 100ms #
# 1s ##################
# 10s+ ################################################################
throttle: 2482 'index not used' warning(s) suppressed.\G
# Query 2: 0.12 QPS, 0.03x concurrency, ID 0x7726D867E0C35FB0 at byte 479767702
# Scores: V/M = 0.00
# Time range: 2018-10-06T19:07:51 to 2018-10-06T19:58:40
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 40 374
# Exec time 6 97s 211ms 390ms 259ms 279ms 20ms 253ms
# Lock time 0 24ms 52us 124us 64us 84us 10us 60us
# Rows sent 55 364.13k 948 1000 996.97 964.41 10.81 964.41
# Rows examine 64 248.93M 587.60k 716.49k 681.56k 683.15k 34.67k 683.15k
# Query size 39 136.55k 283 613 373.88 592.07 85.00 363.48
# String:
# Hosts 192.168.2.39
# Users for_fin_ro
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms ################################################################
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS LIKE 'customer_folxxlx'\G
# SHOW CREATE TABLE `customer_follower`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT `id`, `cusid`, `ownerid`
FROM `cus_follow`
WHERE `ownerid` IN('xxxxx')
AND `del` =0
ORDER BY `id` ASC
LIMIT 1000\G
# Query 3: 0.07 QPS, 1.95x concurrency, ID 0xDDF83730565F004F at byte 479855752
# Scores: V/M = 0.00
# Time range: 2018-10-06T19:53:58 to 2018-10-06T19:54:27
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 2
# Exec time 3 57s 28s 29s 28s 29s 344ms 28s
# Lock time 0 125us 54us 71us 62us 71us 12us 62us
# Rows sent 0 1000 500 500 500 500 0 500
# Rows examine 12 47.31M 23.65M 23.66M 23.66M 23.66M 1.95k 23.66M
# Query size 0 327 163 164 163.50 164 0.71 163.50
# String:
# Hosts 192.168.2.39
# Users for_fin_ro
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+ ################################################################
# Tables
# SHOW TABLE STATUS LIKE 'customer_operaxx'\G
# SHOW CREATE TABLE `customer_operatixx`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT *
FROM `customxxx`
WHERE `op_time` >= '2018-09-24'
AND `op_time` < '2018-10-01'
AND `id` >0
AND `op_type` = 'pull'
ORDER BY `id` ASC
LIMIT 500\G
# Query 4: 0.01 QPS, 0.01x concurrency, ID 0x99F12C2EAC8D0E9F at byte 479735140
# Scores: V/M = 3.92
# Time range: 2018-10-06T19:07:01 to 2018-10-06T19:57:52
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 2 27
# Exec time 2 37s 200ms 10s 1s 5s 2s 266ms
# Lock time 0 3ms 68us 169us 99us 119us 19us 93us
# Rows sent 0 27 1 1 1 1 0 1
# Rows examine 4 16.52M 36.68k 2.90M 626.42k 2.75M 1.03M 112.33k
# Query size 2 10.09k 236 553 382.85 537.02 103.18 329.68
# String:
# Hosts 192.168.2.39
# Users for_fin_ro
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms ################################################################
# 1s ###############
# 10s+ ###
# Tables
# SHOW TABLE STATUS LIKE 'custoxxmer'\G
# SHOW CREATE TABLE `customer`\G
# SHOW TABLE STATUS LIKE 'oms_customer_lidanxx'\G
# SHOW CREATE TABLE `oms_customer_lidxxancount`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT count(customer.id) as total
FROM `customer`
LEFT JOIN `oms_custxer_lidaxxunt` ON `customer`.`id` = `oms_custoxx_lidancount`.`cusid`
WHERE `customer`.`del` = '0'
AND `customer`.`area_id` IN('10', '11', '12', '13', '14', '15', '16', '17', '18', '19', '20', '21', '400', '5', '6', '7', '8', '9', '159', '160', '161', '162', '163', '164'
, '165', '166', '167', '168', '169', '170', '171', '172', '173', '174', '175', '177', '178', '179', '180', '181', '182', '183', '184', '185', '186', '187', '188', '189', '1
90', 0)
AND `customer`.`pool_type` = 1\G
# Query 5: 1.13 QPS, 0.87x concurrency, ID 0x03461C191C644E13 at byte 479419508
# Scores: V/M = 1.90
# Time range: 2018-10-06T19:12:05 to 2018-10-06T19:12:35
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 3 34
# Exec time 1 26s 201ms 6s 771ms 1s 1s 374ms
# Lock time 0 3ms 62us 204us 87us 167us 34us 73us
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 2 10.18M 77.83k 2.22M 306.54k 485.50k 488.38k 144.05k
# Query size 5 17.95k 194 2.64k 540.65 1.96k 640.17 346.17
# String:
# Hosts 192.168.2.39
# Users for_fin
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms ################################################################
# 1s ###########
# 10s+
# Tables
# SHOW TABLE STATUS LIKE 'callrecord'\G
# SHOW CREATE TABLE `callrecord`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT `id`,`operator_id`,`follow_status` FROM callrecord WHERE substring(`calltime`,0,7)='2018-10' AND `operator_id` in (
ccccc/*... omitted 195 items ...*/)\G
上面分了三個部分，第一個部分如下：
# 30.6s user time, 1.8s system time, 27.76M rss, 222.10M vsz # Current date: Sat Oct 6 20:01:11 2018 # Hostname: iz2ze6jo3o3bqbcongnypqz # Files: /alidata1/mysql/data/slow.log # Overall: 924 total, 40 unique, 0.26 QPS, 0.45x concurrency _____________ # Time range: 2018-10-06T19:01:22 to 2018-10-06T20:00:10 # Attribute total min max avg 95% stddev median # ============ ======= ======= ======= ======= ======= ======= ======= # Exec time 1590s 190us 69s 2s 6s 7s 230ms # Lock time 4s 31us 204ms 5ms 21ms 23ms 60us # Rows sent 654.80k 0 23.48k 725.67 964.41 2.54k 6.98 # Rows examine 382.98M 0 23.66M 424.42k 683.15k 1.14M 312.96k # Query size 347.89k 52 59.53k 385.54 592.07 1.88k 271.23
Overall：總共有多少條查詢，本例子為924條
Time range：查詢執行的時間範圍
unique：唯一查詢數量，就是總共有多少個不同的查詢
total：總計時間,min：最小時間，max：最大時間，avg：平均時間
以下是第二部分：
# Profile # Rank Query ID Response time Calls R/Call V/M Item # ==== ================== =============== ===== ======= ===== ============ # 1 0x088884A136067321 1343.1404 84.5% 59 22.7651 11.20 # 2 0x7726D867E0C35FB0 96.6822 6.1% 374 0.2585 0.00 SELECT customer_follower # 3 0xDDF83730565F004F 56.5839 3.6% 2 28.2919 0.00 SELECT customer_operation_log # 4 0x99F12C2EAC8D0E9F 37.1116 2.3% 27 1.3745 3.92 SELECT customer oms_customer_lidancount # 5 0x03461C191C644E13 26.2014 1.6% 34 0.7706 1.90 SELECT callrecord # MISC 0xMISC 29.9696 1.9% 428 0.0700 0.0 <35 ITEMS>
Response：總的響應時間
time：該查詢在本次分析中總的時間佔比
calls：執行次數，即本次分析中總共有多少條這種型別的查詢語句
R/Call：評價每次執行的響應時間
Item:具體的sql語句
其他的就是第三部分，sql語句的詳細輸出結果：
Query_time distribution:查詢時間分佈，長短體現區間佔比
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/20893244/viewspace-2215492/，如需轉載，請註明出處，否則將追究法律責任。