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

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

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

属实诡异

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

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

这两个发出来看下

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

没有分区,就是量大



这能看出来什么吗

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

这个感觉是gc有bug

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

慢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

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

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

来自 @人如其名 的回复:

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

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

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

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

1 个赞

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

参考: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

1 个赞

表妹懂技术了

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

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