TiDB慢查询问题排查

用户85565141446
37 阅读5分钟

背景

刚上线直播间右下角活动入口entrance接口，偶尔会出现依赖上游服务超时问题。开始上游设置的超时时间为300ms，调整为600ms还是有超时。 查看监控发现，下游的耗时都被SQL占用了（注意虽然监控是MySQL但实际为TiDB）：

企业微信20251212-162212.png 阅读上游的rpc方法，发现该rpc的逻辑只有简单的两个查询sql，所以先从SQL慢查询角度去分析了问题。在此记录一下排查过程，可惜的是最后还是没有找到问题原因。

慢查询问题分析

首先分析表DDL，判断查询条件是否命中索引，是否是由于全表扫描导致的。
第一步：在表数据量未知的前提下，我们需要对比业务的查询sql和数据表，是否存在全表扫描的问题。
两个业务查询SQL分别是：

SELECT * FROM `gift_appreciation_task` WHERE 
    task_status = 1 AND 
    start_time <= 1765523523 AND 
    end_time >= 1765523523 
ORDER BY sequence ASC LIMIT 100;

SELECT * FROM `user_gift_appreciation_task_record` WHERE 
    member_id = 1452730773 AND 
    task_id IN (90015);

两张表DDL分别是：（只保留关键字段，其他字段被删掉）

/* gift_appreciation_task */
CREATE TABLE `gift_appreciation_task` (
  `id` bigint(20) NOT NULL AUTO_INCREMENT COMMENT '主键',
  `sequence` int(11) NOT NULL DEFAULT '0' COMMENT '任务序号',
  `task_name` varchar(200) NOT NULL DEFAULT '' COMMENT '任务名称',
  `start_time` bigint(20) NOT NULL DEFAULT '0' COMMENT '开始时间',
  `end_time` bigint(20) NOT NULL DEFAULT '0' COMMENT '结束时间',
  `task_status` tinyint(4) NOT NULL DEFAULT '0' COMMENT '状态: 1-已发布 2-已下架,0-待发布',
  `extra` json DEFAULT NULL COMMENT '扩展配置',
  `created_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP COMMENT '创建时间',
  `updated_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP COMMENT '更新时间',
  PRIMARY KEY (`id`),
  UNIQUE KEY `uniq_sequence` (`sequence`),
  KEY `idx_status` (`task_status`),
  KEY `idx_time_range` (`start_time`,`end_time`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin AUTO_INCREMENT=150001 COMMENT='任务表';

/* user_gift_appreciation_task_record */
CREATE TABLE `user_gift_appreciation_task_record` (
  `id` bigint(20) NOT NULL AUTO_INCREMENT COMMENT '主键',
  `member_id` bigint(20) NOT NULL DEFAULT '0' COMMENT '用户ID',
  `task_id` bigint(20) NOT NULL DEFAULT '0' COMMENT '任务ID',
  `extra` json DEFAULT NULL COMMENT '扩展信息',
  `created_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP COMMENT '创建时间',
  `updated_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP COMMENT '更新时间',
  PRIMARY KEY (`id`),
  UNIQUE KEY `uniq_member_task` (`member_id`,`task_id`),
  KEY `idx_task_id` (`task_id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin AUTO_INCREMENT=150001 COMMENT='任务记录表';

分析表结构发现，该有的索引都有，并且使用explain分析结果，查询也都能命中SQL。是不是表中数据量太大导致的？进一步分析表的数据量，发现表中的数据也不多：

select count(*) from gift_appreciation_task;
> 13

select count(*) from user_gift_appreciation_task_record;
> 1342

到此还需要确认的一点是，是否真的存在慢查询。去DB平台捞一下慢查日志，发现果然存在慢查询日志：

慢查询sql.png 慢查询sql-2.png 由于对TiDB不是很熟悉，接下来的问题分析交给cursor，告诉他问题所在的函数，DDL结构，然后cursor一通分析，这里把cursor的分析结论贴在这里：

  • todo

总结一下cursor的分析结果：

  1. 对 gift_appreciation_task表的查询，索引使用不明确，存在 task_status和start_time都命中的情况，并且sql中用到了排序，建议在代码层面排序。
  2. 对user_gift_appreciation_task_record表的查询，查询条件命中了index，还是出现了慢查询，不慎理解。

优化

  1. 删除表gift_appreciation_task的idx_status索引。删除该索引的原因是，首先，status字段会被频繁修改，并且只有两个值区分度不高。所以在此处优先选择时间索引，把status索引删掉。
    • 观察效果，超时问题还是存在，慢查询也是存在。但是TiDB慢查询在数量和接口层面的超时数量对不上
  2. 对于user_gift_appreciation_task_record这张表，查询条件可以命中uniq_member_task索引，可是还是有慢查询，不可理解。

有如下三张监控图标，分别为：第一张图是RPC接口P99，第二张图依赖该RPC的下游服务接口P99，第三张是TiDB查询P99。通过监控发现，DB的慢查数量和接口的超时数量明显对不上，更关键的是耗时时间也不太吻合。猜测RPC接口超时和慢查询无关。

RPC接口p99.png 下游服务p99.png DB-p99.png 无奈，采用笨办法：在代码中增加日志，确认RPC接口业务逻辑处理的耗时，以此来排查耗时的实际原因。

startTime := time.Now()
defer func() {
    log.Warnf(ctx, "[debug log] GetGiftCollectTaskProgress time: memberId:%v, duration:%v", req.MemberID, time.Since(startTime))
}()

日志打印结果：

image.png image.png image.png 还是跟SQL慢查询有关系。。。。
但是也存在TiDB没有慢查询，接口还会超时的现象： image.png image.png 所以需要在调用方也加一下耗时打印，是否是多个活动串行导致的耗时增加。

TiDB慢查询排查

至此，我们已经完全确认，超时是慢查询导致的。但是不管从DDL索引还是表数据量分析，都不应该存在慢查询。需要尝试分析一下TiDB的explain结果，能否发现一些头绪。 分析explain结果：
explain SELECT * FROM gift_appreciation_task WHERE task_status = 1 AND start_time <= 1765523523 AND end_time >= 1765523523 order by sequence asc limit 100;

idestRowstaskaccess objectoperator info
TopN_90.00root-km_live_activity.gift_appreciation_task.sequence, offset:0, count:100
└─IndexLookUp_220.00root--
├─Selection_19(Build)1.44cop[tikv]-ge(km_live_activity.gift_appreciation_task.end_time, 1765523523)
│ └─IndexRangeScan_174.32cop[tikv]table:gift_appreciation_task, index:idx_time_range(start_time, end_time)range:[-inf,1765523523], keep order:false, stats:pseudo
└─TopN_21(Probe)0.00cop[tikv]-km_live_activity.gift_appreciation_task.sequence, offset:0, count:100
└─Selection_200.00cop[tikv]-eq(km_live_activity.gift_appreciation_task.task_status, 1)
└─TableRowIDScan_181.44cop[tikv]table:gift_appreciation_taskkeep order:false, stats:pseudo

explain SELECT * FROM user_gift_appreciation_task_record WHERE member_id = 1452730773 AND task_id IN (1452730773, 90015);

idestRowstaskaccess objectoperator info
Batch_Point_Get_52.00roottable:user_gift_appreciation_task_record, index:uniq_member_task(member_id, task_id)keep order:false, desc:false

参考文章

cursor分析结果
TiDB查询执行计划的调整及优化原理
TiDB与MySQL的SQL差异及执行计划简析

avatar
文章
阅读
粉丝