pt query digest Analysis of Slow Query Log for MySQL Slow Query

2021-07-10 21:03:14
OfStack

1. Introduction

pt-query-digest is a tool for analyzing mysql slow query. It can analyze binlog, General, log, slowlog, and can also analyze MySQL protocol data captured by SHOWPROCESSLIST or tcpdump. The analysis results can be output to the file. The analysis process is to parameterize the conditions of query statements first, and then group statistics of parameterized queries, and count the execution time, times and proportion of each query. The analysis results can be used to find out problems for optimization.

2. Install pt-query-digest

1. Download page: https://www.percona.com/doc/percona-toolkit/2.2/installation.html

2. Modules for perl


yum install -y perl-CPAN perl-Time-HiRes

3. Installation steps

Method 1: rpm Installation


cd /usr/local/src
wget percona.com/get/percona-toolkit.rpm
yum install -y percona-toolkit.rpm

The tool installation directory is at:/usr/bin

Method 2: Source code installation


cd /usr/local/src
wget percona.com/get/percona-toolkit.tar.gz
tar zxf percona-toolkit.tar.gz
cd percona-toolkit-2.2.19
perl Makefile.PL PREFIX=/usr/local/percona-toolkit
make && make install

The tool installation directory is at:/usr/local/percona-toolkit/bin

4. Brief introduction to the use of various tools (details: https://www.percona.com/doc/percona-toolkit/2.2/index.html)

(1) Slow query log analysis and statistics


pt-query-digest /usr/local/mysql/data/slow.log

(2) Server Summary


pt-summary

(3) Server Disk Monitoring


pt-diskstats

(4) mysql Service Status Summary


pt-mysql-summary -- --user=root --password=root

3. pt-query-digest Syntax and Important Options

pt-query-digest [OPTIONS] [FILES] [DSN] --create-review-table When the analysis results are output to a table using the--review parameter, it is automatically created if there is no table. --create-history-table When the analysis results are output to a table using the--history parameter, it is automatically created if there is no table. --filter matches and filters the input slow query according to the specified string before analyzing it --limit limits the percentage or quantity of output results, and the default value is 20, that is, the slowest 20 statements are output. If it is 50%, it will be sorted from large to small according to the proportion of total response time, and the output will end at the position where the sum reaches 50%. --host mysql server address --user mysql User Name --password mysql User Password --history will save the analysis results to the table, and the analysis results are detailed. When using--history next time, if there are the same statements and the time interval where the query is different from the historical table, it will be recorded in the data table. You can compare the historical changes of a certain type of query by querying the same as 1CHECKSUM. --review will analyze the results saved to the table, this analysis is only parameterized query conditions, 1 type of query 1 record, relatively simple. The next time--review is used, if the same parsing exists, it will not be recorded in the data table. --The output type of output analysis results, the values can be report (standard analysis report), slowlog (Mysql slow log), json, json-anon, and report is generally used for easy reading. --When does since start analysis? The value is a string, which can be a specified time point in the format of "yyyy-mm-dd [hh: mm: ss]", or a simple time value: s (seconds), h (hours), m (minutes), d (days). For example, 12h means starting statistics 12 hours ago. -until deadline, with-since can analyze slow queries in a period of time.

4. Analyze the output of pt-query-digest

Part 1: Overall statistical results

Overall: How many queries are there

Time range: Time range for query execution

unique: Only 1 number of queries, that is, how many different queries are there after the query criteria are parameterized

total: Total min: Minimum max: Max avg: Average

95%: Put all the values in order from small to large, and the number located at 95% has the most reference value

median: Median, arranging all values from small to large, the number in the middle


#  User time, system time, physical memory footprint, virtual memory footprint for log analysis 
# 340ms user time, 140ms system time, 23.99M rss, 203.11M vsz
#  Tool execution time 
# Current date: Fri Nov 25 02:37:18 2016
#  Hostname for running the profiling tool 
# Hostname: localhost.localdomain
#  File name to be parsed 
# Files: slow.log
#  Total number of statements, only 1 The number of statements in the, QPS Concurrent number 
# Overall: 2 total, 2 unique, 0.01 QPS, 0.01x concurrency ________________
#  Time range of logging 
# Time range: 2016-11-22 06:06:18 to 06:11:40
#  Attribute      Total    Minimum   Maximum   Average  95%  Standard   Medium 
# Attribute   total  min  max  avg  95% stddev median
# ============  ======= ======= ======= ======= ======= ======= =======
#  Statement execution time 
# Exec time    3s 640ms  2s  1s  2s 999ms  1s
#  Lock occupancy time 
# Lock time   1ms  0  1ms 723us  1ms  1ms 723us
#  Number of rows sent to client 
# Rows sent    5  1  4 2.50  4 2.12 2.50
# select Number of lines scanned by statement 
# Rows examine  186.17k  0 186.17k 93.09k 186.17k 131.64k 93.09k
#  Number of characters queried 
# Query size   455  15  440 227.50  440 300.52 227.50

Part 2: Query grouping statistics results

Rank: Ranking of all statements, by default in descending order of query time, specified through--order-by

Query ID: ID of the statement, (hash value is calculated by removing redundant spaces and text characters)

Response: Total response time

time: Total time of this query in this analysis

calls: Number of executions, that is, how many queries of this type are there in this analysis

R/Call: Average response time per execution

V/M: Response time ratio of Variance-to-mean

Item: Query Object


# Profile
# Rank Query ID   Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== ===============
# 1 0xF9A57DD5A41825CA 2.0529 76.2%  1 2.0529 0.00 SELECT
# 2 0x4194D8F83F4F9365 0.6401 23.8%  1 0.6401 0.00 SELECT wx_member_base

Part 3: Detailed statistical results of each query

From the detailed statistical results of the following query, the top table lists the statistics of execution times, maximum, minimum, average, 95% and so on.

ID: The queried ID number corresponds to ES223ID in the above figure

Databases: Database name

Users: Number of executions per user (percentage)

Query_time distribution: The query time distribution and length reflect the proportion of intervals. In this example, the number of queries between 1s and 10s is twice that of more than 10s.

Tables: Tables involved in queries

Explain: SQL Statement


# Query 1: 0 QPS, 0x concurrency, ID 0xF9A57DD5A41825CA at byte 802 ______
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2016-11-22 06:11:40
# Attribute pct total  min  max  avg  95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count   50  1
# Exec time  76  2s  2s  2s  2s  2s  0  2s
# Lock time  0  0  0  0  0  0  0  0
# Rows sent  20  1  1  1  1  1  0  1
# Rows examine 0  0  0  0  0  0  0  0
# Query size  3  15  15  15  15  15  0  15
# String:
# Databases test
# Hosts  192.168.8.1
# Users  mysql
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+
# EXPLAIN /*!50100 PARTITIONS*/
select sleep(2)\G

5. Examples of usage

1. Analyze slow query files directly:


cd /usr/local/src
wget percona.com/get/percona-toolkit.rpm
yum install -y percona-toolkit.rpm

2. Analyze queries in the last 12 hours:


cd /usr/local/src
wget percona.com/get/percona-toolkit.rpm
yum install -y percona-toolkit.rpm

3. Analyze queries within the specified time range:


cd /usr/local/src
wget percona.com/get/percona-toolkit.rpm
yum install -y percona-toolkit.rpm

4. Parsing refers to slow queries with select statements


pt-query-digest --filter '$event->{fingerprint} =~ m/^select/i' slow.log> slow_report4.log

5. Slow queries for a user


cd /usr/local/src
wget percona.com/get/percona-toolkit.rpm
yum install -y percona-toolkit.rpm

6. Query all full table scans or full join slow queries


cd /usr/local/src
wget percona.com/get/percona-toolkit.rpm
yum install -y percona-toolkit.rpm

7. Save the query to the query_review table


cd /usr/local/src
wget percona.com/get/percona-toolkit.rpm
yum install -y percona-toolkit.rpm

8. Save the query to the query_history table


cd /usr/local/src
wget percona.com/get/percona-toolkit.rpm
yum install -y percona-toolkit.rpm

9. Grasp the tcp protocol data of mysql through tcpdump, and then analyze it again


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

10. Analysis of binlog


cd /usr/local/src
wget percona.com/get/percona-toolkit.rpm
yum install -y percona-toolkit.rpm

11. Analysis of general log


pt-query-digest --type=genlog localhost.log > slow_report11.log

Summarize