加了索引还这么慢？记一次用skywalking定位慢接口

Galaxy在掘金
1,858 阅读3分钟

平平无奇的营销号标题小能手。害。

太长不看版本 这篇文章讲了啥

  • 慢接口是因为一个select操作。有索引。但是没走索引，索引失效了为什么？还有哪些场景索引也会失效？

  • 通过skywalking定位到了一个慢接口。接口中有很多数据库查询且还有rpc调用，怎么定位是哪一个操作导致慢接口。会介绍怎么使用skywalking的探针缩小范围定位问题。

问题描述

首先介绍下skywalking是什么 请点击 skywalking中国官网

skywalking可以看到所有的慢接口。

点开慢接口以后，可以看到接口进行了哪些操作。

和他们的具体耗时。数据库操作。 rpc调用。

当然除了数据库操作消耗耗时以外，一些内存操作也会耗时。并且由于skywalking只展示了mysql的execute的时间，而mysql的过程其实还包含parser,optimizer等过程，所以有时候会发现一种情况，比如这个接口显示执行了2000ms，但把所有的execute time都加起来还不够2000ms。尤其是，标红，【一些sql索引使用不当，会在mysql的优化过程中产生极大的耗时】，而这些是在execute time中体现不出来的。

比如说，我们这个接口的这个sql语句execute time执行时间100ms。但是从这个接口上一个sql到下一个sql消耗了800ms。时间到哪里去了呢？

           activityRelList = userActivityRelService.list(
                new LambdaQueryWrapper<UserActivityRel>()
                    .in(UserActivityRel::getActivityId, activityIdList));

一个简单的list接口，而且还有索引。测试库模拟了下，通过explain看到确实是用索引。

问题来了，明明加了索引，为什么还这么慢呢？

明明加了索引 为什么这么慢呢

后来到线上数据库去反复找数据执行这个sql，发现有一个activity_id的记录有132200条记录，占总数264402条记录的几乎一半。再加上实际查询的时候是list查询，也就是in id( )。这个数量往往会占总数的三分之二了。这个时候，问题来了，还走索引吗？我们试了试。

单id 132200记录。当然单id走constant。主要是展示一下数量。

explain select * 
from flow_base.user_activity_rel
where activity_id in (6);

顺便抓了个线上日志的参数。

explain select * 
from flow_base.user_activity_rel
where activity_id in (6,12);

有key 却走了全表扫描。

这个时候突然想起来，mysql优化器会根据检索比例,表大小,IO块大小等进行评估是够使用索引。如果使用最优索引搜寻符合条件的数据已经超过30%, 索引就会失效。优化器会走全表扫描。

除此之外，如果使用了

  • 函数，比如date();
  • 模糊搜索，比如like;
  • 范围【where c >= 1 and c< 200】
  • 计算【where b = 1000 + 1】

索引都会失效噢。

最后补一个skywalking的探针用法

前文说过，有的时候耗时的不止mysql，不止rpc，内存计算也是需要跟踪的。 skywalking可以通过注解自定义跟踪范围。

1: 引入依赖

<dependency>
    <groupId>org.apache.skywalking</groupId>
    <artifactId>apm-toolkit-trace</artifactId>
    <version>6.6.0</version>
</dependency>

2: 埋点

@Controller
@Slf4j
public class UserController {
    ...
    @RequestMapping("findAll")
    @ResponseBody
    // 埋点，不指定operationName，默认设置为“类名.方法名”
    @Trace(operationName = "findAll-operationName")
    public List<Person> findAll() {
        // 获取traceId
        log.info(" >>>>> trace id is {} ", TraceContext.traceId());
        // 打标签
        ActiveSpan.tag("这是标记", "标记值");
        // info事件
        ActiveSpan.info("这是一条info日志");
        // debug事件
        ActiveSpan.debug("这是一条debug日志 " + TraceContext.traceId() + " <-前面是id值");
 
        List<Person> all = null;
        try {
            all = personService.findAll();
        } catch (Throwable t) {
            // error事件
            ActiveSpan.error(t);
        }
        return all;
    }

Api 描述

  • TraceContext#traceId 获取traceId
  • ActiveSpan#tag 打标签
  • ActiveSpan#debug debug日志事件
  • ActiveSpan#info info日志事件
  • ActiveSpan#error error异常

3: 最后的效果

avatar
文章
阅读
粉丝