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/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/20893244/viewspace-2215492/