High performance MySQL (2) : Server performance analysis

The article directories

• • preface
  • Introduction to Performance Optimization
  • • Optimization through performance profiling
    • Understanding performance profiling
  • Parsing MySQL query
  • • Slow Query logs
    • pt-query-digest
  • Good information
  • • Slow SQL location analysis

preface

I’m starting a new series on an area I haven’t touched much on before called performance tuning. When I read the word “performance tuning” on my blog, I froze and felt like time stood still. I realized that I had no idea what the performance level of the project code I was writing was, and even if it was bad, how bad it was. The middleware I use, I don’t know how well they perform.

That’s not good.

This series is based on the third edition of High Performance MySQL and is my study notes.

During their technical consulting careers, the three most common performance-related service requests they encountered were how to determine whether a server was performing at its best, how to find out why a statement wasn’t executing fast enough, and how to diagnose some intermittent snags that users described as “stalling,” “stacking-up,” or “jamming.”

The first thing to do is keep the empty glass spirit (for me, my glass is always empty) and get rid of some common misconceptions about performance.

Introduction to Performance Optimization

Starting and stopping measurements at the wrong time measures aggregated information, not the target activity itselfCopy the code

Optimization through performance profiling

Performance profiling typically involves two steps: measuring the time spent on the task; Then sort the results and prioritize the most important tasks.

We will actually discuss two types of performance profiling: execution time-based analysis and wait based analysis. Time-based analysis looks at what tasks take the longest to execute, while wait-based analysis looks at where tasks are blocked the longest.

(Suddenly I feel a little depressed. I can’t understand this chapter all the time. Outside, I always use EXPLAIN, but I always feel there are more core problems. Will it be slow query log?

Pt-qurey-digest, a performance testing tool, will be introduced later.

Understanding performance profiling

Parsing MySQL query

In the current version of MySQL, slow query logging is the cheapest and most accurate tool for measuring query times. The I/O overhead associated with slow log query is negligible, and the concern is that logs can consume a lot of disk space. If slow log query is enabled for a long time, deploy the log rotation tool. Alternatively, do not enable the slow query log function for a long time. Enable the slow query log function only when load samples need to be collected.

Slow Query logs

mysql> show variables like 'slow_query%';
+---------------------+-----------------------------------+
| Variable_name       | Value                             |
+---------------------+-----------------------------------+
| slow_query_log      | OFF                               |
| slow_query_log_file | /var/lib/mysql/localhost-slow.log |
+---------------------+-----------------------------------+
Copy the code

mysql> show variables like 'long_query_time';
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
Copy the code

set global slow_query_log='ON';
set global slow_query_log_file='/var/lib/mysql/instance-1-slow.log';
set global long_query_time=2;
Copy the code

Modify the configuration file to the permanent configuration status: / etc/mysql/conf. D/mysql. CNF/mysqld slow_query_log = ON slow_query_log_file = / var/lib/mysql/instance- 1-slow.log
long_query_time = 2After the configuration is complete, restart MySQL. The test achieves the execution of the problem SQL statement by running the following command: mysql> SELECTsleep(2);
+----------+
| sleep(2) | + -- -- -- -- -- -- -- -- -- -- + |0 |
+----------+
1 row in set (2.00 sec)Then check the slow query log content: $cat /var/lib/mysql.instance-1-slowCopy the code

pt-query-digest

Pt-query-digest is a tool for analyzing slow queries in mysql. It can analyze binlog, General log, and slowlog, as well as 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 the query statement first, and then group the query after parameterization to count the execution time, times and proportion of each query. Problems can be identified and optimized with the help of the analysis results.

Download:

wget https:/ / www.percona.com/downloads/percona-toolkit/3.2.1/binary/redhat/7/x86_64/percona-toolkit-3.2.1-1.el7.x86_64.rpm
Copy the code

ls | grep percona-toolkit3.21.1.el7.x86_64.rpm
Copy the code

PT tools are written and executed in Perl, so you need a Perl environment on your system. Install the associated dependency packages,

[root@xxx ~]# yum install perl-DBI.x86_64
[root@xxx ~]# yum install perl-DBD-MySQL.x86_64
[root@xxx ~]# yum install perl-IO-Socket-SSL.noarch
[root@xxx ~]# yum install perl-Digest-MD5.x86_64
[root@xxx ~]# yum install perl-TermReadKey.x86_64
Copy the code

Install Percona Toolkit:

rpm -iv percona-toolkit3.21.1.el7.x86_64.rpm
Copy the code

rpm -qa | grep percona
Copy the code

Tool directory Installation path: /usr/bin

It’s as slow as a turtle, so I’ll just grab something off the shelf. The acceleration pack has been unable to resolve.

Parsing slow query logs:

pt-query-digest /var/lib/mysql/VM_0_9_centos-slow.log > slow_report.log
Copy the code

The output consists of three parts: Summary information

[root@VM_0_9_centos ~]# more slow_report.log 

# 230ms user time, 20ms system time, 26.35M rss, 220.76M VSZ # CPU and memory usage information # Current date: Wed Aug26 15:44:46 2020# Hostname: VM_0_9_centos /var/lib/mysql/ vm_0_9_centos-slow. log258 total, 37 unique, 0.02 QPS, 0.00x concurrency _____________
# Time range: 2020- 0826 -T11:20:16 to 2020- 0826 -T15:44:11
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time             7s   249us      5s    26ms     4ms   311ms   657us
# Lock time          349ms       0   152ms     1ms   348us    12ms   194us
# Rows sent         33.01k       0   9.77k  131.03  755.64  742.92    0.99
# Rows examine      93.32k       0   9.77k  370.38  874.75  775.00   54.21
# Query size        51.71k      15   7.23k  205.23  223.14  615.30  143.84
Copy the code

Overall: How many queries are there in total2.58K (2580) queries. Time range: Time range for query execution. Note that MySQL57.The time format in this version differs from previous versions. Unique: the number of Unique queries, which is the total number of different queries after the query criteria are parameterized. The case is10A. Attribute: Indicates the Attribute names, such as Exec time and Lock time, described in the Attribute column, as shown in the preceding code segment. Total: indicates statistics of Exec time and Lock time described in the Attribute column. Min: indicates the minimum value of Exec time and Lock time described in the Attribute column. Max: indicates the maximum value of Exec time and Lock time described in the Attribute column. Avg: indicates the average value of the Exec time and Lock time attributes described in the Attribute column.95% : indicates that all the values of Exec time, Lock time and other attributes described in the Attribute column are listed in ascending order, and then the value is located at95The value at the % position (focus on this value). Stddev: Standard deviation, used for distribution statistics of values. Median: indicates the median of Exec time, Lock time and other attributes described by the Attribute column. That is, all values are sorted in ascending order and the value in the middle is takenCopy the code

The second part: parameterize and group the queries, and then analyze the execution of the various queries, ranking the results in order of total execution time

# Profile # Rank Query ID Response time Calls R/Call V/M It # ==== =============================== ============= ===== = = = = = = = = = = = = = #1 0x59A74D08D407B5EDF9A57DD5A4.5.0003 73.7%     1 5.0003  0.00 SELECT
#    2 0x64EF0EA126730002088884A136.0.9650 14.2%     2 0.4825  0.01 
#    3 0x5E1B3DE19F673369DCF52FE6A5.0.3174  4.7%     2 0.1587  0.00 INSERT data_million_a
#    4 0x3992A499999D8F9E3ACC220E0F.0.1334  2.0%     1 0.1334  0.00 ALTER TABLE dtb_table_size `dtb_table_size`
#    5 0x66CAA645BA3ED5433EADC39CCA.0.0991  1.5%     2 0.0495  0.08 SELECT data_million_a
# MISC 0xMISC                           0.2735  4.0%   250 0.0011   0.0 <32 ITEMS>
Copy the code

Rank: indicates the number generated by the query and the Rank of the classification statement in the analysis result set. Query ID: ID of the random string generated for the Query (checksum random string generated based on the fingerprint statement). Response Time: Total Response time of the query and percentage of total Response time of all queries. Calls: The number of times the query was executed, that is, the total number of queries of this type in this analysis. R/Call: average response time for each execution of this query. V/M: ratio of the variance of response time to the mean value. Item: specific query statement object (standardized format conversion statement form: remove specific SELECT fields and table names, WHERE conditions, etc.)Copy the code

Part three: Print the statistics of each statement in descending order according to the total execution time of the statement

# Query 1: 0 QPS, 0x concurrency, ID 0x59A74D08D407B5EDF9A57DD5A41825CA at byte 0
# Scores: V/M = 0.00
# Time range: all events occurred at 2020- 0826 -T11:20:16
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0       1
# Exec time     73      5s      5s      5s      5s      5s       0      5s
# Lock time      0       0       0       0       0       0       0       0
# Rows sent      0       1       1       1       1       1       0       1
# Rows examine   0       0       0       0       0       0       0       0
# Query size     0      15      15      15      15      15       0      15
# String:
# Hosts        localhost
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+
# EXPLAIN / *! 50100 PARTITIONS*/
select sleep(5)\G
Copy the code

Time range: Time range for query execution. Note that MySQL57.The time format in this version differs from previous versions. Attribute: Indicates the Attribute names, such as Count, Exec Time, and Lock time, described in the Attribute column, as shown in the preceding code segment. PCT: represents the grouping statement (here refers to the "Query" in the code snippet above)1"Represents the group statement, specific sentence sample in EXPLAIN... There is output under the keyword. In addition, in the code segment above, calculated values such as total and min are grouped for this statement, which will not be described below) and the proportion of total (statistical value of this statement) to the total statistical value of all statements in the statistical sample. Total: indicates the statistics of the attributes, such as Count, Exec time, and Lock time, described in the Attribute column. Min: indicates the minimum value of Exec time and Lock time described in the Attribute column. Max: indicates the maximum value of Exec time and Lock time described in the Attribute column. Avg: indicates the average value of the Exec time and Lock time attributes described in the Attribute column.95% : indicates that the Exec time, Lock time and other attribute values corresponding to the statement are sorted from large to small, and are located95The value at the % position (focus on this value). Stddev: Standard deviation, used for distribution statistics of values. Median: represents the median value of the corresponding attribute. Rank all values from the smallest to the largest, and take the value in the middle. Databases: database name. Users: indicates the number of times executed by each user (proportion). Query_time distribution: Query time distribution. The length represented by the "#" character indicates the proportion of the statement execution time. As you can see from the code snippet above, the execution time is in1The majority of queries are around S. Tables: SQL sentence text that is generated using the Tables involved in the query statement to query table statistics and table structure. EXPLAIN: represents a sample query statement (easy to copy to view the execution plan. Note that this statement is not randomly generated, but is the worst query SQL statement in the grouping statement)Copy the code

Good information

Slow SQL location analysis

First of all, the slow business system must be reflected in the response time, so in the performance test, if we find the slow response time, we will split it into mysql, that is to analyze the slow SQL, and if we find the mysql process occupies a high CPU in high concurrency, it is also the priority to analyze the existence of slow SQL. And judging slow SQL or relatively simple, for Mysql is to see slow log query.

Get slow SQL, of course, is to actually verify how slow, whether the index is configured, take a test project SQL statement to analyze:

explain SELECT count(c.id)
        FROM administrative_check_content c
        LEFT JOIN administrative_check_report_enforcers e ON c.report_id=e.report_id
        LEFT JOIN administrative_check_report r ON c.report_id = r.id
        WHERE e.enforcer_id= 'ec66d95c8c6d437b9e3a460f93f1a592';
Copy the code

It can be analyzed that 86% of the time was spent Sending data (” Sending data “does not simply send data, but includes” collect [retrieve] + send data “) :

Set profiling=1 is a temporary profiling feature that can be used to cache recent SQL statements (15 by default, up to 100 by default), as shown in figure 2.

Shows whether Profiling is enabled and how many can be storedshow variables like '%profil%'; # open Profilingset profiling=1; # Execute yoursSQL# here we are mainly executing the slowness found earlierSQL# View analysisshow profiles;
Copy the code

From the show profiles we can see the SQL we executed above (Query_ID=18, Query_ID is best set to 25 to ensure that the latest data is monitored)

Run: show profile CPU,memory,block IO for query 18;

Sending data takes 0.39 seconds in total, in which CPU_user takes a high proportion of time (even if a simple SQL statement takes a high proportion of time). In addition, we can also see the IO cost of this SQL statement (because of the query, it is ops out block output).

You can also use SQL lookup to view the above records:

select QUERY_ID,SEQ,STATE,DURATION,CPU_USER,CPU_SYSTEM,BLOCK_OPS_IN,BLOCK_OPS_OUT from information_schema.PROFILING where QUERY_ID = 18
Copy the code

Another note about the show profile statement:

show profile cpu, block io, memory,swaps,context switches,source forquery [Query_ID]; # -cpu: display Cpu related overhead # -block IO: display Block IO related overhead # -context switches: Context switch overhead # -memory: displays Memory overhead # -source: displays overhead information about source_function,source_file, and source_lineCopy the code

Ah, water water water.