Disclaimer: This article may contain information about third-party products. Such information is for reference only. Alibaba Cloud does not make any guarantee, express or implied, with respect to the performance and reliability of third-party products, as well as potential impacts of operations on the products.
Overview
In general, the problem of slow SQL statements often occurs on specific SQL statements, and then the so-called "optimization three axes" are as follows:
| One piece of axe | Plate axe two | Plate axe three |
|
Queries an execution plan. |
Create an appropriate index. | Use appropriate join relationships and filter conditions to implement the optimization of SQL statements. |
However, if the execution plan is correct, the performance of the SQL statement is still slow. How should we locate the bottleneck at this point? For more information, see the following section.
Procedure
To locate the performance problem of an SQL statement more precisely, we need to clearly know how many system resources are consumed when this SQL statement is running. The Profiling tool in MySQL can meet this requirement. You can use this tool to obtain the consumption of multiple resources, such as CPU, I /O, IPC, and SWAP, during the execution of an SQL statement.
Usage of Profiling
The following content shows the basic usage of Profiling in MySQL. For more information, see MySQL official documentation.
Step 1: enable Profiling
After the MySQL database is connected, run the following SQL statement to enable Profiling:
SET profiling = 1;
Step 2: Check the Profiling status
After connecting to the MySQL database, run the following SQL statement to query the Profiling status:
SELECT @@profiling;
The system returns the following content. 0 indicates that Profiling is not enabled and 1 indicates that Profiling is enabled:
+-------------+ | @@profiling | +-------------+ | 1 | +-------------+ 1 row in set (0.00 sec)
Step 3: run the SQL statement used to locate the performance problem
After Profiling is enabled, execute the SQL statement for which you want to locate a performance problem.
CREATE TABLE T1 (id INT);
note: this is an example for reference only. The site is subject to the actual situation.
Step 4: query SQL statement information
Run the following SQL statements to query the information of the saved SQL statements:
SHOW PROFILES;
The system returns the following.
+----------+----------+--------------------------+
| Query_ID | Duration | Query |
+----------+----------+--------------------------+
| 1 | 0.011947 | CREATE TABLE t1 (id INT) |
+----------+----------+--------------------------+
3 rows in set (0.00 sec)
Note:
- Query_ID: the ID number of the SQL statement, which is used in step 5.
- Duration: indicates the Duration of SQL statement execution.
- Query: specific SQL statements.
Step 5: query resource consumption
Run the following SQL statements to query the resource consumption of the specified SQL statements:
SHOW PROFILE CPU, BLOCK IO FOR QUERY [$Query_ID];
Note:
- [$Query_ID]: the ID of the SQL statement for which you want to query resource consumption. You can obtain the ID from step 4.
- "CPU, BLOCK IO" in this SQL statement will only query resource consumption data related to CPU and IO. You can execute this SQL statement to QUERY ALL resource consumption data
SHOW PROFILE ALL FOR QUERY [$Query_ID];.
The system returns the following information. On the page that appears, we can check whether the SQL statement consumes more CPU or I /O resources during execution, and then conduct targeted comparison and analysis. For more information, see
+----------------------+----------+----------+------------+---------------+---------------+ | Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | +----------------------+----------+----------+------------+---------------+---------------+ | checking permissions | 0.000040 | 0.000038 | 0.000002 | 0 | 0 | | creating table | 0.000056 | 0.000028 | 0.000028 | 0 | 0 | | After create | 0.011363 | 0.000217 | 0.001571 | 347 | 347 | | query end | 0.000375 | 0.000013 | 0.000028 | 0 | 0 | | freeing items | 0.000089 | 0.000010 | 0.000014 | 0 | 0 | | logging slow query | 0.000019 | 0.000009 | 0.000010 | 0 | 0 | | cleaning up | 0.000005 | 0.000003 | 0.000002 | 0 | 0 | +----------------------+----------+----------+------------+---------------+---------------+ 7 rows in set (0.00 sec)
Step 6: disable Profiling
After the check is completed, execute the following SQL statement to disable Profiling.
SET profiling = 0;
Troubleshoot slow SQL cases through Profiling
Case description
The following SQL statements are executed on the RDS MySQL moderator instance and read-only instance, respectively. The execution time on the primary instance is 30 seconds, while on the read-only instance is 1 second. The performance difference between the two is quite different.
SELECT COUNT(1)
FROM table_a
WHERE INSTR(col_var, 'abcd') > 0
AND col_id = 108;
Troubleshooting process
- Check the execution plan of the preceding SQL statement by running the
explainstatement on the primary instance and the read-only instance respectively. We find that the other information is consistent except rows, which is slightly different.+----+-------------+---------+------+---------------+--------------+---------+-------+------+-------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | | 1 | SIMPLE | table_a | ref | index_col_id | index_col_id | 9 | const | 2418 | Using where |
+----+-------------+---------+------+---------------+--------------+---------+-------+------+-------------+ - In general, if the execution plans are consistent, the execution performance will not differ too much. The most likely cause of this difference is waiting for locks. For further verification, re-execute the preceding SQL statement on the primary instance. At the same time, open a new Session and execute the
show processliststatement. It is found that the preceding SQL statement is always in the sending data state, which is not waiting for a lock. - Try to rebuild the index and repeat the test without any effect.
- Compared with the table structure on the primary instance and read-only instance, we find that the table structure is completely consistent.
- See usage of Profiling to enable Profiling on the primary and read-only instances, repeat the test on the preceding SQL statements, and then collect the results for comparative analysis. The SQL statements used in this step are as follows.
SET profiling = 1;
SELECT COUNT(1)
FROM table_a
WHERE INSTR(col_var, 'abcd') > 0
AND col_id = 108;
SHOW PROFILECPU, BLOCK IOFOR QUERY 1;
SET profiling = 0; - The profiling results collected on the primary instance and read-only instances are as follows:
- Primary instance
+----------------------+----------+----------+------------+---------------+---------------+ | Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | +----------------------+----------+----------+------------+---------------+---------------+ | continuing | 0.000050 | 0.000000 | 0.000000 | 0 | 0 | | init | 0.000075 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000019 | 0.000000 | 0.000000 | 0 | 0 | | Opening tables | 0.000039 | 0.000000 | 0.000000 | 0 | 0 | | init | 0.000049 | 0.000000 | 0.000000 | 0 | 0 | | System lock | 0.000022 | 0.000000 | 0.000000 | 0 | 0 | | optimizing | 0.000032 | 0.000000 | 0.000000 | 0 | 0 | | statistics | 0.002955 | 0.001000 | 0.000000 | 352 | 0 | | preparing | 0.000037 | 0.000000 | 0.000000 | 0 | 0 | | executing | 0.000017 | 0.000000 | 0.000000 | 0 | 0 | | Sending data |94.410074 | 8.153760 | 1.684743 | 366608 | 110328 | | end | 0.000057 | 0.000000 | 0.000000 | 0 | 0 | | query end | 0.000025 | 0.000000 | 0.000000 | 0 | 0 | | closing tables | 0.000035 | 0.000000 | 0.000000 | 0 | 0 | | freeing items | 0.000040 | 0.000000 | 0.000000 | 0 | 0 | | logging slow query | 0.000027 | 0.000000 | 0.000000 | 0 | 0 | | Opening tables | 0.000030 | 0.000000 | 0.000000 | 0 | 0 | | System lock | 0.000084 | 0.000000 | 0.000000 | 0 | 0 | +----------------------+----------+----------+------------+---------------+---------------+ 18 rows in set (0.01 sec) - Read-only instances supported
+----------------------+----------+----------+------------+---------------+---------------+ | Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out | +----------------------+----------+----------+------------+---------------+---------------+ | continuing | 0.000035 | 0.000000 | 0.000000 | 0 | 0 | | init | 0.000072 | 0.000000 | 0.000000 | 0 | 0 | | checking permissions | 0.000016 | 0.000000 | 0.000000 | 0 | 0 | | Opening tables | 0.000034 | 0.000000 | 0.000000 | 0 | 0 | | init | 0.000049 | 0.000000 | 0.000000 | 0 | 0 | | System lock | 0.000018 | 0.000000 | 0.000000 | 0 | 0 | | optimizing | 0.000028 | 0.000000 | 0.000000 | 0 | 0 | | statistics | 0.000138 | 0.001000 | 0.000000 | 0 | 0 | | preparing | 0.000035 | 0.000000 | 0.000000 | 0 | 0 | | executing | 0.000013 | 0.000000 | 0.000000 | 0 | 0 | | Sending data | 0.992242 | 0.991849 | 0.000000 | 0 | 24 | | end | 0.000035 | 0.000000 | 0.000000 | 0 | 0 | | query end | 0.000018 | 0.000000 | 0.000000 | 0 | 0 | | closing tables | 0.000035 | 0.000000 | 0.000000 | 0 | 0 | | freeing items | 0.000036 | 0.000000 | 0.000000 | 0 | 0 | | logging slow query | 0.000027 | 0.000000 | 0.000000 | 0 | 0 | +----------------------+----------+----------+------------+---------------+---------------+ 16 rows in set (0.01 sec)
- Primary instance
- By comparison, we can see that the Sending data process of the primary instance consumes a large amount of Block_ops_in and Block_ops_out, while the read-only instance is all right. After querying the official website, you can see that the Block_ops_in and Block_ops_out indicate the number of times the device inputs and outputs are block storage, that is, the number of times the data is read from and written to the hard disk. Normally, memory Swap (Swap) is performed by means of hard disks only when the data volume is larger than the available memory. Therefore, such a large number of hard disk reads and writes are generated.
BLOCK_OPS_IN and BLOCK_OPS_OUT indicate the number of block input and output operations.
- After checking the hardware specifications of the primary and read-only instances, you can find that the primary instance only has 2g of memory while the read-only instances have 4G of memory.
Root cause of problem
In this example, the slow SQL statement queries about 4 GB of data, which is equivalent to the memory size of the read-only instance. The read-only instance can store the data in its memory for use. However, the memory size of the Master instance is only 2G, which means it cannot store all the data and requires a large amount of memory exchange. Therefore, it takes a long time.
With the Profiling feature of MySQL, it further confirms which system resources are consumed by slow SQL statements, helping to analyze the performance bottleneck.
Reference
Application scope
- ApsaraDB RDS for MySQL