Hello experts: After upgrading to v6.5.1, some queries have become very slow. What's going on?

Note:
This topic has been translated from a Chinese forum by GPT and might contain errors.

Original topic: 大佬们好:升级v6.5.1后,某些查询变的非常慢,这是怎么了?

| username: jaybing926

[TiDB Usage Environment] Production Environment / Testing / Poc
[TiDB Version] v6.5.1
[Reproduction Path] What operations were performed to encounter the problem
[Encountered Problem: Problem Phenomenon and Impact]
Performed a version upgrade test on the old TiDB cluster from v4.0.9 → v5.0.5 → v6.5.1 (with data but no business running). The upgrade was completed, but some queries became extremely slow (most queries became faster compared to v4.0.9). This particular query took about 40 seconds in v4.0.9, but in v6.5.1 it takes more than 7 minutes, which is significantly slower. I would like to ask what could be the reason for this? How can I troubleshoot it?
The SQL statement is as follows:

The explain information for version v6.5.1 is as follows:

The explain information for version v4.0.9 is as follows:

| username: WalterWj | Original post link

Try changing the states version to 2 and manually collecting the table statistics once.

| username: jaybing926 | Original post link

Bro, what is this states version? I couldn’t find any information about it. Can you explain it in more detail?
Are you referring to tidb_row_format_version?

| username: WalterWj | Original post link

https://docs.pingcap.com/zh/tidb/stable/statistics-analyze-version

| username: jaybing926 | Original post link

Why does this problem occur? I don’t quite understand, and most SQL queries are faster. Do we need to re-run ANALYZE TABLE table_name on all tables? This is too troublesome as we have many tables in our database.

Our old cluster might have been upgraded from version v3.x. Is it because the initial version was too low? Our production cluster’s initial version is v4.0.9. Will we encounter this problem when upgrading to v6.5.1?

| username: tidb菜鸟一只 | Original post link

I don’t see much difference between the two versions of your SQL explain. Aren’t they both using the range scan of the idx_xpost_entryid index? Why is there such a big difference in speed…

| username: db_user | Original post link

This is the execution plan of explain, please post the execution plan of explain analyze.

| username: WalterWj | Original post link

The new version is v2 by default, with some parts of the statistics model refactored. Manually updating it might solve the problem. This is a general solution and may not necessarily work. Slowness needs to be examined case by case for each SQL.

| username: jaybing926 | Original post link

Here is the explain analyze information for the old database v6.0.5:

mysql> 
mysql> explain analyze SELECT xpost.postid, xpost.facetid, xpost.entryid, xpost.title, xpost.url, xpost.abstract, xpost.click, xpost.reply, xpost.repost, xpost.praise, xpost.collect, xpost.wordscount, xpost.siteid, xpost.domain, xpost.author, xpost.author_id, xpost.posttime, xpost.include_t, xpost.type, xpost.source, xpost.hidden, xpost.sourcetype, xpost.crisis_post, xpost.ontop, xpost.type_rank, xpost.pos_type_rank, xpost.noise_rank, xpost.device, xpost.is_origin, xpost.is_top, xpost.media_type, xpost.author_type, xpost.content_type, xpost.client_type, xpost.industry, xpost.tags, xpost.post_type, xpost.type_reason, xpost.update_time, xpost.origin_source, xpost.media_id, xpost.w_level, xpost.watch, xpost.keywordcount, xpost.location, xpost.is_comment, xpost.text, xpost.spider_time, xpost.process_time, xpost.tidb_in_time FROM xpost FORCE INDEX (idx_xpost_entryid) WHERE (xpost.entryid IN (4856577, 4855938, 4856069, 4855686, 4856079, 4857488, 4857618, 4855699, 4856087, 4855966, 4854815, 4855201, 4855714, 4855076, 4851496, 4855083, 4854830, 4856371, 4855608, 4851514, 4857916, 4852797, 4855743, 4851522, 4855748, 4855365, 4851526, 4855624, 4855626, 4856654, 4856018, 4855635, 4855764, 4855637, 4855766, 4854986, 4857305, 4855134, 4855135, 4857706, 4857454, 4855408, 4857211, 4856062) AND (1) AND xpost.hidden IN (-2, -1, 0, 2, 3, 4)) ORDER BY xpost.posttime DESC \G; 
*************************** 1. row ***************************
            id: Sort_5
       estRows: 9978.21
       actRows: 1244055
          task: root
 access object: 
execution info: time:7m37.3s, loops:1216
 operator info: bsppr.xpost.posttime:desc
        memory: 956.7 MB
          disk: 1.06 GB
*************************** 2. row ***************************
            id: └─Projection_7
       estRows: 9978.21
       actRows: 1244055
          task: root
 access object: 
execution info: time:7.45s, loops:1216, Concurrency:5
 operator info: bsppr.xpost.postid, bsppr.xpost.facetid, bsppr.xpost.entryid, bsppr.xpost.title, bsppr.xpost.url, bsppr.xpost.abstract, bsppr.xpost.click, bsppr.xpost.reply, bsppr.xpost.repost, bsppr.xpost.praise, bsppr.xpost.collect, bsppr.xpost.wordscount, bsppr.xpost.siteid, bsppr.xpost.domain, bsppr.xpost.author, bsppr.xpost.author_id, bsppr.xpost.posttime, bsppr.xpost.include_t, bsppr.xpost.type, bsppr.xpost.source, xpost.hidden, xpost.sourcetype, xpost.crisis_post, xpost.ontop, xpost.type_rank, xpost.pos_type_rank, xpost.noise_rank, xpost.device, xpost.is_origin, xpost.is_top, xpost.media_type, xpost.author_type, xpost.content_type, xpost.client_type, xpost.industry, xpost.tags, xpost.post_type, xpost.type_reason, xpost.update_time, xpost.origin_source, xpost.media_id, xpost.w_level, xpost.watch, xpost.keywordcount, xpost.location, xpost.is_comment, xpost.text, xpost.spider_time, xpost.process_time, xpost.tidb_in_time
        memory: 4.49 MB
          disk: N/A
*************************** 3. row ***************************
            id:   └─IndexLookUp_11
       estRows: 9978.21
       actRows: 1244055
          task: root
 access object: 
execution info: time:7.83s, loops:1216, index_task: {total_time: 7.32s, fetch_handle: 131.1ms, build: 197.4µs, wait: 7.18s}, table_task: {total_time: 38s, num: 65, concurrency: 5}, next: {wait_index: 2.97ms, wait_table_lookup_build: 1.05ms, wait_table_lookup_resp: 3.67s}
 operator info: 
        memory: 181.9 MB
          disk: N/A
*************************** 4. row ***************************
            id:     ├─IndexRangeScan_8(Build)
       estRows: 83843.43
       actRows: 1244114
          task: cop[tikv]
 access object: table:xpost, index:idx_xpost_entryid(entryid)
execution info: time:27.3ms, loops:1237, cop_task: {num: 138, max: 194.7ms, min: 1.23ms, avg: 24ms, p95: 106.5ms, max_proc_keys: 50144, p95_proc_keys: 50144, tot_proc: 930ms, tot_wait: 127ms, rpc_num: 138, rpc_time: 3.31s, copr_cache_hit_ratio: 0.09, distsql_concurrency: 15}, tikv_task:{proc max:59ms, min:0s, avg: 7.15ms, p80:9ms, p95:28ms, iters:1742, tasks:138}, scan_detail: {total_process_keys: 1192678, total_process_keys_size: 54863188, total_keys: 1482570, get_snapshot_time: 134.4ms, rocksdb: {delete_skipped_count: 19, key_skipped_count: 1482423, block: {cache_hit_count: 2451, read_count: 5, read_byte: 83.5 KB, read_time: 207.5µs}}}
 operator info: range:[4851496,4851496], [4851514,4851514], [4851522,4851522], [4851526,4851526], [4852797,4852797], [4854815,4854815], [4854830,4854830], [4854986,4854986], [4855076,4855076], [4855083,4855083], [4855134,4855134], [4855135,4855135], [4855201,4855201], [4855365,4855365], [4855408,4855408], [4855608,4855608], [4855624,4855624], [4855626,4855626], [4855635,4855635], [4855637,4855637], [4855686,4855686], [4855699,4855699], [4855714,4855714], [4855743,4855743], [4855748,4855748], [4855764,4855764], [4855766,4855766], [4855938,4855938], [4855966,4855966], [4856018,4856018], [4856062,4856062], [4856069,4856069], [4856079,4856079], [4856087,4856087], [4856371,4856371], [4856577,4856577], [4856654,4856654], [4857211,4857211], [4857305,4857305], [4857454,4857454], [4857488,4857488], [4857618,4857618], [4857706,4857706], [4857916,4857916], keep order:false
        memory: N/A
          disk: N/A
*************************** 5. row ***************************
            id:     └─Selection_10(Probe)
       estRows: 9978.21
       actRows: 1244055
          task: cop[tikv]
 access object: 
execution info: time:37s, loops:1354, cop_task: {num: 8457, max: 1.28s, min: 728.6µs, avg: 51.8ms, p95: 218.7ms, max_proc_keys: 16590, p95_proc_keys: 636, tot_proc: 56.4s, tot_wait: 12.9s, rpc_num: 8457, rpc_time: 7m17.7s, copr_cache_hit_ratio: 0.09, distsql_concurrency: 15}, tikv_task:{proc max:620ms, min:0s, avg: 7.78ms, p80:7ms, p95:35ms, iters:15378, tasks:8457}, scan_detail: {total_process_keys: 1078696, total_process_keys_size: 739576989, total_keys: 1227196, get_snapshot_time: 12.6s, rocksdb: {delete_skipped_count: 16, key_skipped_count: 413543, block: {cache_hit_count: 11354691, read_count: 5, read_byte: 80.2 KB, read_time: 1.37ms}}}
 operator info: in(bsppr.xpost.hidden, -2, -1, 0, 2, 3, 4)
        memory: N/A
          disk: N/A
*************************** 6. row ***************************
            id:       └─TableRowIDScan_9
       estRows: 83843.43
       actRows: 1244114
          task: cop[tikv]
 access object: table:xpost
execution info: tikv_task:{proc max:620ms, min:0s, avg: 7.76ms, p80:7ms, p95:35ms, iters:15378, tasks:8457}
 operator info: keep order:false
        memory: N/A
          disk: N/A
6 rows in set (7 min 37.55 sec)

Since the old database has been upgraded and cannot be rolled back to explain, here is the explain analyze information for the production database v4.0.9:

MySQL [bsppr]> 
MySQL [bsppr]> 
MySQL [bsppr]> explain analyze SELECT xpost.postid, xpost.facetid, xpost.entryid, xpost.title, xpost.url, xpost.abstract, xpost.click, xpost.reply, xpost.repost, xpost.praise, xpost.collect, xpost.wordscount, xpost.siteid, xpost.domain, xpost.author, xpost.author_id, xpost.posttime, xpost.include_t, xpost.type, xpost.source, xpost.hidden, xpost.sourcetype, xpost.crisis_post, xpost.ontop, xpost.type_rank, xpost.pos_type_rank, xpost.noise_rank, xpost.device, xpost.is_origin, xpost.is_top, xpost.media_type, xpost.author_type, xpost.content_type, xpost.client_type, xpost.industry, xpost.tags, xpost.post_type, xpost.type_reason, xpost.update_time, xpost.origin_source, xpost.media_id, xpost.w_level, xpost.watch, xpost.keywordcount, xpost.location, xpost.is_comment, xpost.text, xpost.spider_time, xpost.process_time, xpost.tidb_in_time FROM xpost FORCE INDEX (idx_xpost_entryid) WHERE (xpost.entryid IN (4856577, 4855938, 4856069, 4855686, 4856079, 4857488, 4857618, 4855699, 4856087, 4855966, 4854815, 4855201, 4855714, 4855076, 4851496, 4855083, 4854830, 4856371, 4855608, 4851514, 4857916, 4852797, 4855743, 4851522, 4855748, 4855365, 4851526, 4855624, 4855626, 4856654, 4856018, 4855635, 4855764, 4855637, 4855766, 4854986, 4857305, 4855134, 4855135, 4857706, 4857454, 4855408, 4857211, 4856062) AND (1) AND xpost.hidden IN (-2, -1, 0, 2, 3, 4)) ORDER BY xpost.posttime DESC\G;  
*************************** 1. row ***************************
            id: Sort_5
       estRows: 27643.42
       actRows: 1244179
          task: root
 access object: 
execution info: time:24.614187157s, loops:1217
 operator info: bsppr.xpost.posttime:desc
        memory: 982.008674621582 MB
          disk: 1.2011287668719888 GB
*************************** 2. row ***************************
            id: └─Projection_7
       estRows: 27643.42
       actRows: 1244179
          task: root
 access object: 
execution info: time:7.16124316s, loops:1217, Concurrency:4
 operator info: bsppr.xpost.postid, bsppr.xpost.facetid, bsppr.xpost.entryid, bsppr.xpost.title, bsppr.xpost.url, bsppr.xpost.abstract, bsppr.xpost.click, bsppr.xpost.reply, bsppr.xpost.repost, bsppr.xpost.praise, bsppr.xpost.collect, bsppr.xpost.wordscount, bsppr.xpost.siteid, bsppr.xpost.domain, bsppr.xpost.author, bsppr.xpost.author_id, bsppr.xpost.posttime, bsppr.xpost.include_t, bsppr.xpost.type, bsppr.xpost.source, xpost.hidden, xpost.sourcetype, xpost.crisis_post, xpost.ontop, xpost.type_rank, xpost.pos_type_rank, xpost.noise_rank, xpost.device, xpost.is_origin, xpost.is_top, xpost.media_type, xpost.author_type, xpost.content_type, xpost.client_type, xpost.industry, xpost.tags, xpost.post_type, xpost.type_reason, xpost.update_time, xpost.origin_source, xpost.media_id, xpost.w_level, xpost.watch, xpost.keywordcount, xpost.location, xpost.is_comment, xpost.text, xpost.spider_time, xpost.process_time, xpost.tidb_in_time
        memory: 3.3519744873046875 MB
          disk: N/A
*************************** 3. row ***************************
            id:   └─IndexLookUp_11
       estRows: 27643.42
       actRows: 1244179
          task: root
 access object: 
execution info: time:7.18731351s, loops:1217, index_task:35.031861ms, table_task:{num:64, concurrency:4, time:28.32257032s}
 operator info: 
        memory: 115.38516521453857 MB
          disk: N/A
*************************** 4. row ***************************
            id:     ├─IndexRangeScan_8(Build)
       estRows: 98574.13
       actRows: 1244179
          task: cop[tikv]
 access object: table:xpost, index:idx_xpost_entryid(entryid)
execution info: time:6.61509143s, loops:64, cop_task: {num: 18, max: 446.377326ms, min: 1.085309ms, avg: 56.777582ms, p95: 446.377326ms, max_proc_keys: 601446, p95_proc_keys: 601446, tot_proc: 685ms, tot_wait: 24ms, rpc_num: 18, rpc_time: 1.021157901s, copr_cache_hit_ratio: 0.00}, tikv_task:{proc max:284ms, min:0s, p80:50ms, p95:284ms, iters:1288, tasks:18}
 operator info: range:[4851496,4851496], [4851514,4851514], [4851522,4851522], [4851526,4851526], [4852797,4852797], [4854815,4854815], [4854830,4854830], [4854986,4854986], [4855076,4855076], [4855083,4855083], [4855134,4855134], [4855135,4855135], [4855201,4855201], [4855365,4855365], [4855408,4855408], [4855608,4855608], [4855624,4855624], [4855626,4855626], [4855635,4855635], [4855637,4855637], [4855686,4855686], [4855699,4855699], [4855714,4855714], [4855743,4855743], [4855748,4855748], [4855764,4855764], [4855766,4855766], [4855938,4855938], [
| username: db_user | Original post link

Try removing the order by and see if it works. It looks like an issue with the sort operator.

| username: jaybing926 | Original post link

Yes, after removing the ORDER BY, the speed is directly 8 seconds. What’s going on?

mysql> explain analyze SELECT xpost.postid, xpost.facetid, xpost.entryid, xpost.title, xpost.url, xpost.abstract, xpost.click, xpost.reply, xpost.repost, xpost.praise, xpost.collect, xpost.wordscount, xpost.siteid, xpost.domain, xpost.author, xpost.author_id, xpost.posttime, xpost.include_t, xpost.type, xpost.source, xpost.hidden, xpost.sourcetype, xpost.crisis_post, xpost.ontop, xpost.type_rank, xpost.pos_type_rank, xpost.noise_rank, xpost.device, xpost.is_origin, xpost.is_top, xpost.media_type, xpost.author_type, xpost.content_type, xpost.client_type, xpost.industry, xpost.tags, xpost.post_type, xpost.type_reason, xpost.update_time, xpost.origin_source, xpost.media_id, xpost.w_level, xpost.watch, xpost.keywordcount, xpost.location, xpost.is_comment, xpost.text, xpost.spider_time, xpost.process_time, xpost.tidb_in_time FROM xpost FORCE INDEX (idx_xpost_entryid) WHERE (xpost.entryid IN (4856577, 4855938, 4856069, 4855686, 4856079, 4857488, 4857618, 4855699, 4856087, 4855966, 4854815, 4855201, 4855714, 4855076, 4851496, 4855083, 4854830, 4856371, 4855608, 4851514, 4857916, 4852797, 4855743, 4851522, 4855748, 4855365, 4851526, 4855624, 4855626, 4856654, 4856018, 4855635, 4855764, 4855637, 4855766, 4854986, 4857305, 4855134, 4855135, 4857706, 4857454, 4855408, 4857211, 4856062) AND (1) AND xpost.hidden IN (-2, -1, 0, 2, 3, 4))  \G;
*************************** 1. row ***************************
            id: Projection_4
       estRows: 9978.21
       actRows: 1244055
          task: root
 access object: 
execution info: time:7.85s, loops:1216, Concurrency:5
 operator info: bsppr.xpost.postid, bsppr.xpost.facetid, bsppr.xpost.entryid, bsppr.xpost.title, bsppr.xpost.url, bsppr.xpost.abstract, bsppr.xpost.click, bsppr.xpost.reply, bsppr.xpost.repost, bsppr.xpost.praise, bsppr.xpost.collect, bsppr.xpost.wordscount, bsppr.xpost.siteid, bsppr.xpost.domain, bsppr.xpost.author, bsppr.xpost.author_id, bsppr.xpost.posttime, bsppr.xpost.include_t, bsppr.xpost.type, bsppr.xpost.source, bsppr.xpost.hidden, bsppr.xpost.sourcetype, bsppr.xpost.crisis_post, bsppr.xpost.ontop, bsppr.xpost.type_rank, bsppr.xpost.pos_type_rank, bsppr.xpost.noise_rank, bsppr.xpost.device, bsppr.xpost.is_origin, bsppr.xpost.is_top, bsppr.xpost.media_type, bsppr.xpost.author_type, bsppr.xpost.content_type, bsppr.xpost.client_type, bsppr.xpost.industry, bsppr.xpost.tags, bsppr.xpost.post_type, bsppr.xpost.type_reason, bsppr.xpost.update_time, bsppr.xpost.origin_source, bsppr.xpost.media_id, bsppr.xpost.w_level, bsppr.xpost.watch, bsppr.xpost.keywordcount, bsppr.xpost.location, bsppr.xpost.is_comment, bsppr.xpost.text, bsppr.xpost.spider_time, bsppr.xpost.process_time, bsppr.xpost.tidb_in_time
        memory: 13.6 MB
          disk: N/A
*************************** 2. row ***************************
            id: └─IndexLookUp_8
       estRows: 9978.21
       actRows: 1244055
          task: root
 access object: 
execution info: time:7.85s, loops:1216, index_task: {total_time: 7.21s, fetch_handle: 126ms, build: 183.1µs, wait: 7.09s}, table_task: {total_time: 37.9s, num: 65, concurrency: 5}, next: {wait_index: 10.9ms, wait_table_lookup_build: 53.4ms, wait_table_lookup_resp: 6.33s}
 operator info: 
        memory: 174.5 MB
          disk: N/A
*************************** 3. row ***************************
            id:   ├─IndexRangeScan_5(Build)
       estRows: 83843.43
       actRows: 1244114
          task: cop[tikv]
 access object: table:xpost, index:idx_xpost_entryid(entryid)
execution info: time:13ms, loops:1239, cop_task: {num: 138, max: 134.1ms, min: 362µs, avg: 15ms, p95: 71.5ms, max_proc_keys: 50144, p95_proc_keys: 50144, tot_proc: 842ms, tot_wait: 80ms, rpc_num: 138, rpc_time: 2.07s, copr_cache_hit_ratio: 0.09, distsql_concurrency: 15}, tikv_task:{proc max:70ms, min:0s, avg: 6.7ms, p80:10ms, p95:26ms, iters:1742, tasks:138}, scan_detail: {total_process_keys: 1194726, total_process_keys_size: 54957396, total_keys: 1484878, get_snapshot_time: 86ms, rocksdb: {delete_skipped_count: 18, key_skipped_count: 1484732, block: {cache_hit_count: 2400, read_count: 10, read_byte: 159.9 KB, read_time: 294µs}}}
 operator info: range:[4851496,4851496], [4851514,4851514], [4851522,4851522], [4851526,4851526], [4852797,4852797], [4854815,4854815], [4854830,4854830], [4854986,4854986], [4855076,4855076], [4855083,4855083], [4855134,4855134], [4855135,4855135], [4855201,4855201], [4855365,4855365], [4855408,4855408], [4855608,4855608], [4855624,4855624], [4855626,4855626], [4855635,4855635], [4855637,4855637], [4855686,4855686], [4855699,4855699], [4855714,4855714], [4855743,4855743], [4855748,4855748], [4855764,4855764], [4855766,4855766], [4855938,4855938], [4855966,4855966], [4856018,4856018], [4856062,4856062], [4856069,4856069], [4856079,4856079], [4856087,4856087], [4856371,4856371], [4856577,4856577], [4856654,4856654], [4857211,4857211], [4857305,4857305], [4857454,4857454], [4857488,4857488], [4857618,4857618], [4857706,4857706], [4857916,4857916], keep order:false
        memory: N/A
          disk: N/A
*************************** 4. row ***************************
            id:   └─Selection_7(Probe)
       estRows: 9978.21
       actRows: 1244055
          task: cop[tikv]
 access object: 
execution info: time:34.5s, loops:1362, cop_task: {num: 8238, max: 1.28s, min: 669.6µs, avg: 47.2ms, p95: 215.9ms, max_proc_keys: 20480, p95_proc_keys: 630, tot_proc: 55.6s, tot_wait: 9.34s, rpc_num: 8238, rpc_time: 6m28.8s, copr_cache_hit_ratio: 0.11, distsql_concurrency: 15}, tikv_task:{proc max:724ms, min:0s, avg: 8.1ms, p80:7ms, p95:35ms, iters:15178, tasks:8238}, scan_detail: {total_process_keys: 1056051, total_process_keys_size: 721790478, total_keys: 1205112, get_snapshot_time: 8.88s, rocksdb: {delete_skipped_count: 19, key_skipped_count: 417205, block: {cache_hit_count: 11070198, read_count: 55, read_byte: 677.0 KB, read_time: 6.7ms}}}
 operator info: in(bsppr.xpost.hidden, -2, -1, 0, 2, 3, 4)
        memory: N/A
          disk: N/A
*************************** 5. row ***************************
            id:     └─TableRowIDScan_6
       estRows: 83843.43
       actRows: 1244114
          task: cop[tikv]
 access object: table:xpost
execution info: tikv_task:{proc max:723ms, min:0s, avg: 8.07ms, p80:7ms, p95:35ms, iters:15178, tasks:8238}
 operator info: keep order:false
        memory: N/A
          disk: N/A
5 rows in set (7.86 sec)
| username: jaybing926 | Original post link

mysql> explain analyze SELECT xpost.postid, xpost.facetid, xpost.entryid, xpost.title, xpost.url, xpost.abstract, xpost.click, xpost.reply, xpost.repost, xpost.praise, xpost.collect, xpost.wordscount, xpost.siteid, xpost.domain, xpost.author, xpost.author_id, xpost.posttime, xpost.include_t, xpost.type, xpost.source, xpost.hidden, xpost.sourcetype, xpost.crisis_post, xpost.ontop, xpost.type_rank, xpost.pos_type_rank, xpost.noise_rank, xpost.device, xpost.is_origin, xpost.is_top, xpost.media_type, xpost.author_type, xpost.content_type, xpost.client_type, xpost.industry, xpost.tags, xpost.post_type, xpost.type_reason, xpost.update_time, xpost.origin_source, xpost.media_id, xpost.w_level, xpost.watch, xpost.keywordcount, xpost.location, xpost.is_comment, xpost.text, xpost.spider_time, xpost.process_time, xpost.tidb_in_time FROM xpost FORCE INDEX (idx_xpost_entryid) WHERE (xpost.entryid IN (4856577, 4855938, 4856069, 4855686, 4856079, 4857488, 4857618, 4855699, 4856087, 4855966, 4854815, 4855201, 4855714, 4855076, 4851496, 4855083, 4854830, 4856371, 4855608, 4851514, 4857916, 4852797, 4855743, 4851522, 4855748, 4855365, 4851526, 4855624, 4855626, 4856654, 4856018, 4855635, 4855764, 4855637, 4855766, 4854986, 4857305, 4855134, 4855135, 4857706, 4857454, 4855408, 4857211, 4856062) AND (1) AND xpost.hidden IN (-2, -1, 0, 2, 3, 4))  ;

+---------------------------------+----------+---------+-----------+-----------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+------+
| id                              | estRows  | actRows | task      | access object                                 | execution info                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                           | operator info                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    | memory   | disk |
+---------------------------------+----------+---------+-----------+-----------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+------+
| Projection_4                    | 9978.21  | 1244055 | root      |                                               | time:7.66s, loops:1216, Concurrency:5                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    | bsppr.xpost.postid, bsppr.xpost.facetid, bsppr.xpost.entryid, bsppr.xpost.title, bsppr.xpost.url, bsppr.xpost.abstract, bsppr.xpost.click, bsppr.xpost.reply, bsppr.xpost.repost, bsppr.xpost.praise, bsppr.xpost.collect, bsppr.xpost.wordscount, bsppr.xpost.siteid, bsppr.xpost.domain, bsppr.xpost.author, bsppr.xpost.author_id, bsppr.xpost.posttime, bsppr.xpost.include_t, bsppr.xpost.type, bsppr.xpost.source, bsppr.xpost.hidden, bsppr.xpost.sourcetype, bsppr.xpost.crisis_post, bsppr.xpost.ontop, bsppr.xpost.type_rank, bsppr.xpost.pos_type_rank, bsppr.xpost.noise_rank, bsppr.xpost.device, bsppr.xpost.is_origin, bsppr.xpost.is_top, bsppr.xpost.media_type, bsppr.xpost.author_type, bsppr.xpost.content_type, bsppr.xpost.client_type, bsppr.xpost.industry, bsppr.xpost.tags, bsppr.xpost.post_type, bsppr.xpost.type_reason, bsppr.xpost.update_time, bsppr.xpost.origin_source, bsppr.xpost.media_id, bsppr.xpost.w_level, bsppr.xpost.watch, bsppr.xpost.keywordcount, bsppr.xpost.location, bsppr.xpost.is_comment, bsppr.xpost.text, bsppr.xpost.spider_time, bsppr.xpost.process_time, bsppr.xpost.tidb_in_time | 13.5 MB  | N/A  |
| └─IndexLookUp_8                 | 9978.21  | 1244055 | root      |                                               | time:7.65s, loops:1216, index_task: {total_time: 7.01s, fetch_handle: 130ms, build: 278.5µs, wait: 6.88s}, table_task: {total_time: 37s, num: 65, concurrency: 5}, next: {wait_index: 2.65ms, wait_table_lookup_build: 1.06ms, wait_table_lookup_resp: 6.02s}                                                                                                                                                                                                                                                                                                                                                                                            |                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                  | 159.2 MB | N/A  |
|   ├─IndexRangeScan_5(Build)     | 83843.43 | 1244114 | cop[tikv] | table:xpost, index:idx_xpost_entryid(entryid) | time:16.7ms, loops:1239, cop_task: {num: 138, max: 461ms, min: 570.3µs, avg: 25.4ms, p95: 105.4ms, max_proc_keys: 50144, p95_proc_keys: 50144, tot_proc: 974ms, tot_wait: 221ms, rpc_num: 138, rpc_time: 3.51s, copr_cache_hit_ratio: 0.07, distsql_concurrency: 15}, tikv_task:{proc max:69ms, min:0s, avg: 7.51ms, p80:10ms, p95:32ms, iters:1742, tasks:138}, scan_detail: {total_process_keys: 1213094, total_process_keys_size: 55802324, total_keys: 1506275, get_snapshot_time: 235.3ms, rocksdb: {delete_skipped_count: 19, key_skipped_count: 1506126, block: {cache_hit_count: 2468, read_count: 2, read_byte: 36.3 KB, read_time: 30.2µs}}}   | range:[4851496,4851496], [4851514,4851514], [4851522,4851522], [4851526,4851526], [4852797,4852797], [4854815,4854815], [4854830,4854830], [4854986,4854986], [4855076,4855076], [4855083,4855083], [4855134,4855134], [4855135,4855135], [4855201,4855201], [4855365,4855365], [4855408,4855408], [4855608,4855608], [4855624,4855624], [4855626,4855626], [4855635,4855635], [4855637,4855637], [4855686,4855686], [4855699,4855699], [4855714,4855714], [4855743,4855743], [4855748,4855748], [4855764,4855764], [4855766,4855766], [4855938,4855938], [4855966,4855966], [4856018,4856018], [4856062,4856062], [4856069,4856069], [4856079,4856079], [4856087,4856087], [4856371,4856371], [4856577,4856577], [4856654,4856654], [4857211,4857211], [4857305,4857305], [4857454,4857454], [4857488,4857488], [4857618,4857618], [4857706,4857706], [4857916,4857916], keep order:false                                                                                                                                                                       | N/A      | N/A  |
|   └─Selection_7(Probe)          | 9978.21  | 1244055 | cop[tikv] |                                               | time:36s, loops:1362, cop_task: {num: 8355, max: 1.18s, min: 652.6µs, avg: 51.5ms, p95: 228.9ms, max_proc_keys: 14779, p95_proc_keys: 623, tot_proc: 57.7s, tot_wait: 13s, rpc_num: 8355, rpc_time: 7m9.7s, copr_cache_hit_ratio: 0.10, distsql_concurrency: 15}, tikv_task:{proc max:603ms, min:0s, avg: 8.15ms, p80:7ms, p95:35ms, iters:15331, tasks:8355}, scan_detail: {total_process_keys: 1063027, total_process_keys_size: 728082827, total_keys: 1211079, get_snapshot_time: 12.5s, rocksdb: {delete_skipped_count: 16, key_skipped_count: 413568, block: {cache_hit_count: 11172803, read_count: 5, read_byte: 21.2 KB, read_time: 21.1µs}}}   | in(bsppr.xpost.hidden, -2, -1, 0, 2, 3, 4)                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                       | N/A      | N/A  |
|     └─TableRowIDScan_6          | 83843.43 | 1244114 | cop[tikv] | table:xpost                                   | tikv_task:{proc max:601ms, min:0s, avg: 8.12ms, p80:7ms, p95:35ms, iters:15331, tasks:8355}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                              | keep order:false                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 | N/A      | N/A  |
+---------------------------------+----------+---------+-----------+-----------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+------+
5 rows in set (7.66 sec)

mysql>
| username: db_user | Original post link

Then it is indeed the sort operator causing the slowness. First, check the resources, such as memory, etc. Then check the health of this table, see if there are frequent analyze operations by looking at show analyze status, etc. Additionally, provide the table structure of this table. Also, check the parameter configurations of both environments.

| username: jaybing926 | Original post link

I found this slow SQL in the PD dashboard. Is this the maximum memory for this SQL?

This is my tidb_mem_quota_query variable information. Is it because the memory usage of this SQL exceeded the maximum memory, causing it to slow down?
image

| username: jaybing926 | Original post link

It seems that by adjusting the memory, the speed has improved. Thank you, expert!!

mysql> SET tidb_mem_quota_query = 8 << 30;
Query OK, 0 rows affected (0.00 sec)

mysql> SET tidb_mem_quota_query = 8 << 30;
Query OK, 0 rows affected (0.00 sec)

mysql> SELECT xpost.postid, xpost.facetid, xpost.entryid, xpost.title, xpost.url, xpost.abstract, xpost.click, xpost.reply, xpost.repost, xpost.praise, xpost.collect, xpost.wordscount, xpost.siteid, xpost.domain, xpost.author, xpost.author_id, xpost.posttime, xpost.include_t, xpost.type, xpost.source, xpost.hidden, xpost.sourcetype, xpost.crisis_post, xpost.ontop, xpost.type_rank, xpost.pos_type_rank, xpost.noise_rank, xpost.device, xpost.is_origin, xpost.is_top, xpost.media_type, xpost.author_type, xpost.content_type, xpost.client_type, xpost.industry, xpost.tags, xpost.post_type, xpost.type_reason, xpost.update_time, xpost.origin_source, xpost.media_id, xpost.w_level, xpost.watch, xpost.keywordcount, xpost.location, xpost.is_comment, xpost.text, xpost.spider_time, xpost.process_time, xpost.tidb_in_time FROM xpost FORCE INDEX (idx_xpost_entryid) WHERE (xpost.entryid IN (4856577, 4855938, 4856069, 4855686, 4856079, 4857488, 4857618, 4855699, 4856087, 4855966, 4854815, 4855201, 4855714, 4855076, 4851496, 4855083, 4854830, 4856371, 4855608, 4851514, 4857916, 4852797, 4855743, 4851522, 4855748, 4855365, 4851526, 4855624, 4855626, 4856654, 4856018, 4855635, 4855764, 4855637, 4855766, 4854986, 4857305, 4855134, 4855135, 4857706, 4857454, 4855408, 4857211, 4856062) AND (1) AND xpost.hidden IN (-2, -1, 0, 2, 3, 4)) ORDER BY xpost.posttime DESC;  
1244055 rows in set (30.22 sec)

mysql> 
mysql> 
mysql>
| username: db_user | Original post link

You’re welcome. It seems that the sort operator is using the disk because the memory is too small, but you also need to monitor it to avoid OOM due to excessive memory usage.

| username: jaybing926 | Original post link

Okay :kiss: :kiss: :kiss:

| username: 人如其名 | Original post link

Adjusting the memory can temporarily solve the problem. I see that your 4.x version also has disk spill situations, but it is not very slow. However, in version 6.5, it takes 7 minutes for just over a million records, which is abnormal even if it involves disk spilling; it’s too slow. I think it needs a deeper analysis. We need to check where the main time consumption is in the pprof.

| username: 人如其名 | Original post link

I tested it myself, but it was version 7.0, and it was also very slow. The test results are as follows:

mysql> select version();
+--------------------+
| version()          |
+--------------------+
| 5.7.25-TiDB-v7.0.0 |
+--------------------+
1 row in set (0.00 sec)
mysql> explain analyze select * from customer order by C_ADDRESS desc;
+-------------------------+-------------+----------+-----------+----------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------+-----------+---------+
| id                      | estRows     | actRows  | task      | access object  | execution info                                                                                                                                                                                                                                                                                                                                                       | operator info                   | memory    | disk    |
+-------------------------+-------------+----------+-----------+----------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------+-----------+---------+
| Sort_4                  | 15000000.00 | 15000000 | root      |                | time:11m31.8s, loops:14650, RRU:94859.635554, WRU:0.000000                                                                                                                                                                                                                                                                                                           | tpch100.customer.c_address:desc | 1011.0 MB | 3.09 GB |
| └─TableReader_8         | 15000000.00 | 15000000 | root      |                | time:17.4s, loops:14686, cop_task: {num: 565, max: 2.18s, min: 2.13ms, avg: 430.5ms, p95: 1.3s, max_proc_keys: 50144, p95_proc_keys: 50144, tot_proc: 2m24.4s, tot_wait: 1.22s, rpc_num: 565, rpc_time: 4m3.2s, copr_cache_hit_ratio: 0.00, build_task_duration: 17.4ms, max_distsql_concurrency: 15}                                                                | data:TableFullScan_7            | 180.3 MB  | N/A     |
|   └─TableFullScan_7     | 15000000.00 | 15000000 | cop[tikv] | table:customer | tikv_task:{proc max:1.86s, min:1ms, avg: 302.2ms, p80:559ms, p95:916ms, iters:16879, tasks:565}, scan_detail: {total_process_keys: 15000000, total_process_keys_size: 3052270577, total_keys: 15000565, get_snapshot_time: 262.7ms, rocksdb: {key_skipped_count: 15000000, block: {cache_hit_count: 5046, read_count: 49981, read_byte: 1.13 GB, read_time: 32.1s}}} | keep order:false                | N/A       | N/A     |
+-------------------------+-------------+----------+-----------+----------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------------------+-----------+---------+
3 rows in set (11 min 32.36 sec)

Looking at the time, the actual sorting takes very little time. The main time is spent on 1) reading data from the disk with chunk.(*rowInDisk).ReadFrom (an ongoing issue); 2) the chunk.New function, where a lot of CPU time is ultimately consumed by calling runtime.mallocgc after using the object.

Therefore, I don’t know if there have been changes compared to version 4.x when reading data from the disk into memory and creating new chunks. It seems like a lot of time is spent on garbage collection after the chunk data is returned to the client. If we could use a technique similar to arena for manual large block (multiple consecutive chunks) recycling, I wonder if the performance would be better.

| username: jaybing926 | Original post link

I have 5.8 billion entries in this xpost table, and I don’t understand what’s going on with this one million plus.