Record a troubleshooting process when the database CPU is full

1 Introduction Recently, with the increase of data volume, the 100% CPU usage of the database alarms frequently. The first thing that comes to my mind is slow Sql. After we added indexes to tables that did not use indexes reasonably, the problem was still not solved. During in-depth investigation, it was found that when order by id asc limit n was used, even if the where condition already included a covering index, The optimizer still chose the wrong index. The problem was solved by querying a lot of data. Here, the ideas for solving the problem and the troubleshooting process will be shared. If there are any mistakes, please correct me.

2 text
2.1 Environment introduction

2.2 Find the problem
From the 22nd, the following alarms in Figure 1 became more frequent. Due to the large data push action in the database, the occasional alarm of the database CPU did not attract attention to the problem until the analysis of the daily monitoring data through Figure 2 , only to discover the seriousness of the problem. Starting from 0:00, the database CPU is frequently full.

Figure 1: Alarm Diagram

Figure 2: All day CPU monitoring graph

2.3 Troubleshooting After finding the problem, I started to troubleshoot slow Sql, and found that many queries did not add appropriate indexes. After a round of repairs, the problem was still not solved. During the in-depth investigation, a strange phenomenon was found. The SQL code is as follows (the table name has been Replace), a relatively simple single-table query statement.

 SELECT
    *
FROM
    test 
WHERE
    is_delete = 0 
    AND business_day = '2021-12-20' 
    AND full_ps_code LIKE  'xxx%'
    AND id > 2100
ORDER BY
    id 
    LIMIT 500;

It seems to be a relatively simple query, but the average execution time is more than 90s, and the call frequency is high. As shown in Figure 3.

Figure 3: Average execution time of slow SQL

Start to check the table information, you can see that the amount of table data is about 2100w.

Figure 4: Data sheet situation

Check the index situation, the primary key is id, and there is a joint index of business_day and full_ps_code.

 PRIMARY KEY (`id`) USING BTREE,
  KEY `idx_business_day_full_ps_code` (`business_day`,`full_ps_code`)
  ==========以下索引可以忽略========
  KEY `idx_erp_month_businessday` (`erp`,`month`,`business_day`),
  KEY `idx_business_day_erp` (`business_day`,`erp`),
  KEY `idx_erp_month_ps_plan_id` (`erp`,`month`,`ps_performance_plan_id`),
  ......

When viewing the execution plan through Explain, it is found that possible_keys contains the above joint index, but Key selects the Primary primary key index, and the number of rows scanned is 1700w, which is almost equal to a full table scan.

Figure 5: Execution of the plan

2.4 Solving the problem For the first time, our analysis is that because the Where condition contains ID, the query analyzer thinks that the number of rows scanned by the primary key index will be less, and at the same time, it is more reasonable to use the primary key index to sort according to the primary key. We try to add the following index, We want the query analyzer to hit our newly added index.

 ADD INDEX `idx_test`(`business_day`, `full_ps_code`, `id`) USING BTREE;

Through the analysis of the Explain statement again, it is found that the execution plan has not changed at all, and the primary key index is still used.

 explain
SELECT
    *
FROM
    test 
WHERE
    is_delete = 0 
    AND business_day = '2021-12-20' 
    AND full_ps_code LIKE  'xxx%'
    AND id > 2100
ORDER BY
    id 
    LIMIT 500;

Figure 6: Execution of the plan

For the second time, we analyzed the execution situation again by forcing the specified index method force index (idx_test), and obtained the results in Figure 7. The same query conditions have the same results, and the query time is about 90s->0.49s. problem solved

Figure 7: Execution plan after forcing an index to be specified

The third time, we suspect that there is an ID in the where condition that causes the primary key index to go directly. The id is removed from the where condition, and Sql is adjusted as follows, and then analyzes. Still no index hit, scan rows become 111342, query time 96s

 SELECT
    *
FROM
    test 
WHERE
    is_delete = 0 
    AND business_day = '2021-12-20' 
    AND full_ps_code LIKE  'xxx%'
ORDER BY
    id 
    LIMIT 500

The fourth time, we removed the order by, adjusted the SQL as follows, and then analyzed it. The joint index created before idx_business_day_full_ps_code was hit. The number of scanned rows becomes 154900, and the query time becomes 0.062s, but the result is found to be inconsistent with the expected, and disorder occurs

 SELECT
    *
FROM
    test 
WHERE
    is_delete = 0 
    AND business_day = '2021-12-20' 
    AND full_ps_code LIKE  'xxx%'
    AND id > 2100
LIMIT 500;

The fifth time, after the previous analysis, it can be determined that the order by causes the query analyzer to select the primary key index. We add a sort field in the order by, and adjust the Sql as follows, which can also hit our previous joint index, and the query time is 0.034s, since the primary key is sorted first, the results are consistent. Compared with the fourth method, there is one more filesort, and the problem has to be solved.

 SELECT
    *
FROM
    test 
WHERE
    is_delete = 0 
    AND business_day = '2021-12-20' 
    AND full_ps_code LIKE  'xxx%'
    AND id > 2100
ORDER BY
    id，full_ps_code
    LIMIT 500;

The sixth time, we considered whether the problem was caused by the Limit. We adjusted the Limit 500 to 1000, and the Sql was adjusted as follows, a miracle happened, the joint index was hit, the query time was 0.316s, and the results were the same, but 500 more items were returned. data. Problem solved. After many experiments, when the Limit is greater than 695, the joint index will be hit. The amount of data under the query condition is 79963, and the ratio of 696/79963 is about 0.0087. It is guessed that when the data ratio exceeds 0.0087, the joint index will be selected, and the source code is not found. verify this conclusion.

 SELECT
    *
FROM
    test 
WHERE
    is_delete = 0 
    AND business_day = '2021-12-20' 
    AND full_ps_code LIKE  'xxx%'
    AND id > 2100
ORDER BY
    id 
    LIMIT 1000;

After our verification, the 2nd, 5th, and 6th methods can all solve the performance problem. In order not to affect the online, we immediately modified the code and chose the method of force index. After a period of online observation, the database CPU returned to normal, and the problem was solved.

3 Post-mortem analysis

After going online, the problem has been solved, but it also left me with a lot of questions.

Why is it that the joint index is included in the where condition, but it fails to hit, and instead the primary key index with slower performance is selected?
Why is it possible to hit the joint index by adding an index to other fields in order by?
Why can I hit the joint index only after I increase the limit limit from the original 500?
The answer to all this comes from MySQL's query optimizer.

3.1 Query Optimizer The query optimizer is an optimizer module specially responsible for optimizing query statements. It provides the optimal execution plan for the query by calculating and analyzing various system statistical information collected—the optimal data retrieval method.

The way the optimizer decides how to execute a query is based on a method called cost-based optimization. 5.7 In terms of cost types, it is divided into IO, CPU, and Memory. The memory cost is collected, but does not participate in the final cost calculation. Mysql introduces two system tables, mysql.server_cost and mysql.engine_cost, server_cost corresponds to the cost of CPU, and engine_cost represents the cost of IO.

server_cost (CPU cost)
row_evaluate_cost (default 0.2) Calculate the cost of eligible rows. The more rows, the greater the cost
memory_temptable_create_cost (default 2.0) The creation cost of the memory temporary table
memory_temptable_row_cost (default 0.2) row cost of memory temporary table
key_compare_cost (default 0.1) cost of key comparison, such as sorting
disk_temptable_create_cost (default 40.0) Internal myisam or innodb temporary table creation cost
disk_temptable_row_cost (default 1.0) The row cost of the internal myisam or innodb temporary table It can be seen from the above that the cost of creating a temporary table is very high, especially the internal myisam or innodb temporary table.

engine_cost (IO cost)
io_block_read_cost (default 1.0) The cost of reading data from disk, for innodb, it means the cost of reading a page from disk
memory_block_read_cost (default 1.0) The cost of reading data from memory. For innodb, it means the cost of reading a page from the buffer pool. These information can be configured in the database. When not configured in the database, from the MySql source code (5.7) You can see the above default values

3.2 Cost Configuration

 --修改io_block_read_cost值为2
UPDATE mysql.engine_cost
  SET cost_value = 2.0
  WHERE cost_name = 'io_block_read_cost';
--FLUSH OPTIMIZER_COSTS 生效，只对新连接有效，老连接无效。
FLUSH OPTIMIZER_COSTS;

3.3 How to calculate the cost? You can find the final answer by reading the source code of MySql

3.3.1 Full table scan (table_scan_cost)
The following code is taken from MySql Server (5.7 branch), the calculation method of IO and CPU cost during full table scan.

 double scan_time=
   cost_model->row_evaluate_cost(static_cast<double>(records)) + 1;
// row_evaluate_cost 核心代码
// rows * m_server_cost_constants->row_evaluate_cost() 
// 数据行数 * 0.2 (row_evaluate_cost默认值) + 1 = CPU代价
Cost_estimate cost_est= head->file->table_scan_cost();
//table_scan_cost 核心代码
//const double io_cost 
//     = scan_time() * table->cost_model()->page_read_cost(1.0)
// 这部分代价为IO部分
//page_read_cost 核心代码
//
//const double in_mem= m_table->file->table_in_memory_estimate();
//
// table_in_memory_estimate 核心逻辑
//如果表的统计信息中提供了信息,使用统计信息，如果没有则使用启发式估值计算
//pages=1.0
//
//const double pages_in_mem= pages * in_mem;
//const double pages_on_disk= pages - pages_in_mem;
//
//
//计算出两部分IO的代价之和
//const double cost= buffer_block_read_cost(pages_in_mem) +
//  io_block_read_cost(pages_on_disk);
//
//
//buffer_block_read_cost 核心代码
// pages_in_mem比例 * 1.0 （memory_block_read_cost的默认值）
// blocks * m_se_cost_constants->memory_block_read_cost()
//
//
//io_block_read_cost 核心代码
//pages_on_disk * 1.0 （io_block_read_cost的默认值）
//blocks * m_se_cost_constants->io_block_read_cost();
 //返回IO与CPU代价
 //这里增加了个系数调整，原因未知
 cost_est.add_io(1.1);
 cost_est.add_cpu(scan_time);

According to the source code analysis, when the table contains 100 rows of data, the cost of full table scan is 23.1, and the calculation logic is as follows

 //CPU代价 = 总数据行数 * 0.2 (row_evaluate_cost默认值) + 1 
cpu_cost = 100 * 0.2 + 1 等于 21
io_cost = 1.1 + 1.0 等于 2.1
//总成本 = cpu_cost + io_cost = 21 + 2.1 = 23.1

The verification result is as follows

3.3.2 Index scan (index_scan_cost)

The following code is excerpted from MySql Server (5.7 branch), how to calculate when an index scan occurs, the core code is as follows

 //核心代码解析
*cost= index_scan_cost(keyno, static_cast<double>(n_ranges),
                         static_cast<double>(total_rows));
cost->add_cpu(cost_model->row_evaluate_cost(
        static_cast<double>(total_rows)) + 0.01)

io cost calculation core code

 //核心代码
 const double io_cost= index_only_read_time(index, rows) *
   table->cost_model()->page_read_cost_index(index, 1.0);
// index_only_read_time(index, rows)
// 估算index占page个数
//page_read_cost_index(index, 1.0)
//根据buffer pool大小和索引大小来估算page in memory和in disk的比例，计算读一个page的代价

CPU cost calculation core code

 add_cpu(cost_model->row_evaluate_cost(
        static_cast<double>(total_rows)) + 0.01);
//total_rows 等于索引过滤后的总行数
//row_evaluate_cost 与全表扫描的逻辑类似，
//区别在与一个是table_in_memory_estimate一个是index_in_memory_estimate

3.3.3 Other methods

There are many ways to calculate the cost. For other ways, please refer to the original MySql code. https://github.com/mysql/mysql-server.git

3.4 In-depth analysis By viewing optimizer_trace, you can understand how the query optimizer selects the index.

 set optimizer_trace="enabled=on";
--如果不设置大小，可能导致json输出不全
set OPTIMIZER_TRACE_MAX_MEM_SIZE=1000000;
SELECT
    *
FROM
    test 
WHERE
    is_delete = 0 
    AND business_day = '2021-12-20' 
    AND full_ps_code LIKE  'xxx%'
    AND id > 0
ORDER BY
    id 
    LIMIT 500;
select * FROM information_schema.optimizer_trace;
set optimizer_trace="enabled=off";

By analyzing the rows_estimation node, you can see that the cost of a full table scan (table_scan) is 8.29e6, and you can also see that the query can select the primary key index and the joint index, as shown below.

The cost of the full table scan in the above figure is 8.29e6. We convert it to 8,290,000 in the ordinary counting method. If the primary key index is used, the cost is 3,530,000, and the joint index is 185,881. The smallest should be the joint index of 185,881. You can also see the cost of passing the first step Analysis did choose our joint index.

But why choose the primary key index?

By looking down, under the considering_access_paths_for_index_ordering node, it is found that the index has been re-selected due to Order by. In the following figure, you can see that the primary key index is available (usable=true), and our joint index is not_applicable (not applicable), which means that the order is only A primary key index can be used.

Next, it can be seen from index_order_summary that the execution plan is finally adjusted, from the original joint index to the primary key index, which means that this choice ignores the previous choice based on index cost.

The main reasons why there is such an option are as follows:
The short explanation is that the optimizer thinks — or should I say hopes — that scanning the whole table (which is already sorted by the id field) will find the limited rows quick enough, and that this will avoid a sort operation. So by trying to avoid a sort, the optimizer ends-up losing time scanning the table.

It can be seen from this explanation that the main reason is that because we use order by id asc, the id-based sorting method, the optimizer thinks sorting is an expensive operation, so in order to avoid sorting, and it thinks that limit n is small if n is small Even if a full table scan is used, it can be executed quickly, so it chooses a full table scan, which avoids the sorting of ids.

5 Summary <br>The query optimizer will select the optimal execution plan based on cost, but due to the existence of order by id limit n, MySql may reselect a wrong index and ignore the original index selected based on cost. Instead, choose a primary key index for a full table scan. This problem has a lot of user feedback at home and abroad, the BUG address is https://bugs.mysql.com/bug.php?id=97001 . Officials say that in versions after 5.7.33, you can turn off prefer_ordering_index to solve it. As shown below.

In addition, in our daily slow Sql tuning, we can learn more about the query optimizer selection process in the following two ways.

 --第一种
explain format=json
sql语句
-------------------------------------------------------------------------
--第二种 optimizer_trace方式
set optimizer_trace="enabled=on";
--如果不设置大小，可能导致json输出不全
set OPTIMIZER_TRACE_MAX_MEM_SIZE=1000000;
SQL语句
select * FROM information_schema.optimizer_trace;
set optimizer_trace="enabled=off";

When you also have the problem encountered in this article, you can use the following methods to solve

Use force index to force the specified index.
Add a joint index key to order by.
Expand the range returned by limit (not recommended, as the amount of data increases, it may go back to the primary key index)
order by (id+0) asc tricks the query optimizer into choosing a union index.
For MySQL version 5.7.33 and above, you can turn off prefer_ordering_index to solve the problem.

Author: Chen Qiang