SQL 查询超过2分钟，执行计划显示limit慢

考试没答案 · 2023 年3 月 22 日 01:17

您不加 limit 出来的是 16秒。多少条数据呢？？？

h5n1 · 2023 年3 月 22 日 01:35

show variables like ‘%tidb_enable_paging%’
trace select SQL 执行结果

liuis · 2023 年3 月 22 日 02:52

属实诡异

大飞飞呀 · 2023 年3 月 22 日 04:23

表总数量24亿，但是status=0的不到1000条

考试没答案 · 2023 年3 月 22 日 05:27

show stats_healthy where table_name like ‘%bk_student_exam_chunk%’;
show stats_meta where table_name like ‘%bk_student_exam_chunk%’;

这两个发出来看下

tidb菜鸟一只 · 2023 年3 月 22 日 07:50

确实有问题，正常应该是下面的执行时间更短。。。。你这个表是不是有很多的分区啊？

大飞飞呀 · 2023 年3 月 22 日 11:05

没有分区，就是量大

大飞飞呀 · 2023 年3 月 22 日 11:08

这能看出来什么吗

Jellybean · 2023 年3 月 22 日 13:48

执行计划里看有pseudo关键字，表明统计信息过期了=，可以使用 analyze table 更新下统计信息，然后再执行看是否符合预期

大飞飞呀 · 2023 年3 月 24 日 09:42

这个感觉是gc有bug

yilong · 2023 年3 月 27 日 02:20

麻烦将两个 SQL 的完整的执行计划发一下。

大飞飞呀 · 2023 年5 月 22 日 09:22

慢SQL:
EXPLAIN ANALYZE SELECT * from st_summary_bill_sync_confirm
WHERE I_ID in (
SELECT I_ID FROM XXXXX use index (IDX_SYNC_STATUS)
WHERE I_SYNC_STATUS = 0 limit 100
)

IndexJoin_21, 100.00, 100, root, , time:4m27.2s, loops:2, inner:{total:2.22ms, concurrency:8, task:2, construct:135µs, fetch:2.03ms, build:54.3µs}, probe:62.8µs, inner join, inner:TableReader_18, outer key:stat.st_summary_bill_sync_confirm.i_id, inner key:stat.st_summary_bill_sync_confirm.i_id, equal cond:eq(stat.st_summary_bill_sync_confirm.i_id, stat.st_summary_bill_sync_confirm.i_id), 168.1 KB, N/A
├─Limit_28(Build), 100.00, 100, root, , time:4m27.2s, loops:5, offset:0, count:100, N/A, N/A
│ └─IndexReader_33, 100.00, 100, root, , time:4m27.2s, loops:3, cop_task: {num: 2094, max: 939.9ms, min: 39.7ms, avg: 127.5ms, p95: 197.4ms, max_proc_keys: 100, p95_proc_keys: 0, tot_proc: 4m20.6s, tot_wait: 3.18s, rpc_num: 2098, rpc_time: 4m27s, copr_cache_hit_ratio: 0.00}, backoff{regionMiss: 2ms}, index:Limit_32, 1.88 KB, N/A
│ └─Limit_32, 100.00, 100, cop[tikv], , tikv_task:{proc max:371ms, min:39ms, p80:139ms, p95:190ms, iters:2096, tasks:2094}, scan_detail: {total_process_keys: 100, total_keys: 1114637287, rocksdb: {delete_skipped_count: 105025, key_skipped_count: 1115454747, block: {cache_hit_count: 656203, read_count: 570, read_byte: 11.0 MB}}}, offset:0, count:100, N/A, N/A
│ └─IndexRangeScan_31, 100.00, 100, cop[tikv], table:st_summary_bill_sync_confirm, index:IDX_SYNC_STATUS(I_SYNC_STATUS), tikv_task:{proc max:371ms, min:39ms, p80:139ms, p95:190ms, iters:2096, tasks:2094}, scan_detail: {total_process_keys: 0, total_keys: 0, rocksdb: {delete_skipped_count: 0, key_skipped_count: 0, block: {cache_hit_count: 0, read_count: 0, read_byte: 0 Bytes}}}, range:[0,0], keep order:false, N/A, N/A
└─TableReader_18(Probe), 1.00, 100, root, , time:1.75ms, loops:4, cop_task: {num: 2, max: 891.3µs, min: 703.3µs, avg: 797.3µs, p95: 891.3µs, max_proc_keys: 96, p95_proc_keys: 96, rpc_num: 2, rpc_time: 1.54ms, copr_cache_hit_ratio: 0.00}, data:TableRangeScan_17, N/A, N/A
└─TableRangeScan_17, 1.00, 100, cop[tikv], table:st_summary_bill_sync_confirm, tikv_task:{proc max:0s, min:0s, p80:0s, p95:0s, iters:4, tasks:2}, scan_detail: {total_process_keys: 100, total_keys: 302, rocksdb: {delete_skipped_count: 0, key_skipped_count: 300, block: {cache_hit_count: 23, read_count: 2, read_byte: 21.0 KB}}}, range: decided by [stat.st_summary_bill_sync_confirm.i_id], keep order:false, N/A, N/A

快SQL:
EXPLAIN ANALYZE SELECT * from st_summary_bill_sync_confirm
WHERE I_ID in (
SELECT I_ID FROM st_summary_bill_sync_confirm use index (IDX_SYNC_STATUS)
WHERE I_SYNC_STATUS = 0
)

IndexJoin_19, 7656372.52, 503708, root, , time:2.59s, loops:493, inner:{total:1.45s, concurrency:8, task:28, construct:472ms, fetch:816.3ms, build:158.7ms}, probe:261.2ms, inner join, inner:TableReader_16, outer key:stat.st_summary_bill_sync_confirm.i_id, inner key:stat.st_summary_bill_sync_confirm.i_id, equal cond:eq(stat.st_summary_bill_sync_confirm.i_id, stat.st_summary_bill_sync_confirm.i_id), 52.7 MB, N/A
├─IndexReader_39(Build), 7656372.52, 503708, root, , time:2.23s, loops:498, cop_task: {num: 2094, max: 459.4ms, min: 196.2µs, avg: 13.1ms, p95: 112.8ms, max_proc_keys: 503708, p95_proc_keys: 0, tot_proc: 25.6s, tot_wait: 699ms, rpc_num: 2101, rpc_time: 27.3s, copr_cache_hit_ratio: 0.91}, backoff{regionMiss: 2ms}, index:IndexRangeScan_38, 7.70 MB, N/A
│ └─IndexRangeScan_38, 7656372.52, 503708, cop[tikv], table:st_summary_bill_sync_confirm, index:IDX_SYNC_STATUS(I_SYNC_STATUS), tikv_task:{proc max:455ms, min:60ms, p80:149ms, p95:210ms, iters:2589, tasks:2094}, scan_detail: {total_process_keys: 503708, total_keys: 107064050, rocksdb: {delete_skipped_count: 8864, key_skipped_count: 107225632, block: {cache_hit_count: 62788, read_count: 299, read_byte: 18.2 MB}}}, range:[0,0], keep order:false, N/A, N/A
└─TableReader_16(Probe), 1.00, 503708, root, , time:653.1ms, loops:545, cop_task: {num: 28, max: 37.6ms, min: 811.9µs, avg: 22.3ms, p95: 36.4ms, max_proc_keys: 25600, p95_proc_keys: 25600, tot_proc: 519ms, tot_wait: 13ms, rpc_num: 28, rpc_time: 622.8ms, copr_cache_hit_ratio: 0.00}, data:TableRangeScan_15, N/A, N/A
  └─TableRangeScan_15, 1.00, 503708, cop[tikv], table:st_summary_bill_sync_confirm, tikv_task:{proc max:25ms, min:0s, p80:23ms, p95:25ms, iters:625, tasks:28}, scan_detail: {total_process_keys: 503708, total_keys: 535144, rocksdb: {delete_skipped_count: 3007, key_skipped_count: 537412, block: {cache_hit_count: 9620, read_count: 755, read_byte: 9.69 MB}}}, range: decided by [stat.st_summary_bill_sync_confirm.i_id], keep order:false, N/A, N/A

Billmay表妹 · 2023 年5 月 22 日 09:46

执行计划参考这个来贴：【SOP 系列 21】AskTUG SQL执行计划上传规范

wakaka · 2023 年5 月 22 日 10:19

大量的GC未回收完数据导致扫描数据过多

Billmay表妹 · 2023 年5 月 22 日 11:05

来自 @人如其名的回复：

你做limit时候会不停的给tikv请求coptask，针对每一个都要做limit 1 的请求。但是当region数据都被清理但是并没有被gc时候会导致大量的region扫描，却始终找不到数据。找到第一条数据时候已经扫过了太多的region了。

这种在传统数据库中也经常遇到，表被做了大量数据删除也是查找一条记录非常慢。但有一些关系型数据库统计信息会把碎片问题做进去，如果表碎片特别多那么就直接走主键索引了。

lsmtree结构的需要做gc，等同于碎片整理。因此可能不会做这块的实现。但是你需要及时的gc，默认10分钟，你延迟了比较久我估计是有慢语句卡住了，或者其他原因导致gc没有推进。

在gc方面找下原因，我理解这个并不是bug。@大飞飞jeffery

TiDBer_iLonNMYE · 2023 年5 月 23 日 00:50

听起来有点类似Oracle的延迟块清理。
“做limit时候会不停的给tikv请求coptask，针对每一个都要做limit 1 的请求”，请问为什么是limit 1不是limit 100?

TiDBer_iLonNMYE · 2023 年5 月 23 日 01:09

参考：GC 正常，key_skipped_count 远大于 total_process_keys，导致 SQL 性能问题 - #7，来自 RaftSnail

bug-11217: 多key GC调用导致GC不工作，大量历史版本残留影响版本 v5.0.0-v5.0.4 v5.1.0-v5.1.2 v5.1.4 v5.2.0-v5.2.2 issue: https://github.com/tikv/tikv/issues/11217 TiKV GcKeys task doesn’t work when called with multiple keys

程序员小王 · 2023 年5 月 23 日 02:22

表妹懂技术了

人如其名 · 2023 年5 月 23 日 05:50

笔误，是limit 100。另外看他这个执行计划都是走的索引，limit 100慢是因为limit导致查询缓存失效的问题，没有做limit就可以走查询缓存。这点通过这个指标可以看出来：copr_cache_hit_ratio: 0.91。
他这个问题还是大佬们讲的GC的bug导致，然后引起的性能问题。

大飞飞呀 · 2023 年5 月 23 日 06:23

添加limit：total_process_keys: 100, total_keys: 1114637287（11亿）
去除limit：total_process_keys: 503708, total_keys: 107064050 （10亿）
这是为什么呢