Plain old marketing headline whiz. Pollution.

Too long to see the version of this article about what

  • The slow interface is due to a SELECT operation. There is an index. But it missed the index. The index failed. Why? What other scenarios will the index fail?

  • A slow interface was located via Skywalking. There are many database queries and RPC calls in the interface. How to locate which operation is causing the slow interface? We’ll show you how to narrow down the problem using Skywalking’s probe.

Problem description

First, what is Skywalking? Please click on the official website of Skywalking China

Skywalking can see all the slow interfaces.

After clicking on the slow interface, you can see what the interface is doing.

And how long they take. Database operations.RPC calls.

Of course, in addition to database operations, some memory operations can also be time-consuming. In addition, skywalking only shows the time of mysql execute, and the mysql process also includes parser, Optimizer and other processes. Therefore, it is sometimes found that this interface displays the execution time of 2000ms. But adding up all the Execute time is not enough for 2000ms. In particular, in red, [some SQL indexes are used improperly, which can cause a significant amount of time in mysql optimization], which is not reflected in execute Time.

For example, the SQL statement execute time of our interface is 100ms. But it takes 800ms to get from one SQL on this interface to the next. Where did the time go?

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

A simple list interface with an index. Test library simulation, through explain to see that does use the index.

The question is, why is the index so slow?

Why is the index so slow

Later, I went to the online database to repeatedly find the data to execute this SQL, and found that there was a record of activity_id with 132200 records, accounting for almost half of the total 264402 records. Plus the actual query is a list query, which is in id(). This often accounts for two-thirds of the total. At this time, the question comes, still go index? We gave it a try.

Single ID 132200 Record. Of course the single ID goes constant. The main thing is to show the quantity.

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

I grabbed an online log parameter by the way.

Explain select * from flow_base. User_activity_rel where activity_id in (6,12);Copy the code

There is a key but went full table scan.

It occurs to me that the mysql optimizer will evaluate whether an index is sufficient to use based on the size of the index, table size,IO block size, etc. If more than 30% of the eligible data has been searched using the optimal index, the index is invalidated. The optimizer does a full table scan.

In addition, if used

  • Functions, such as date();
  • Fuzzy search, like like;
  • Where c >= 1 and c< 200
  • Where b = 1000 + 1

The index will fail.

Finally, add a probe usage for Skywalking

As mentioned earlier, sometimes not only mysql, not only RPC, but also memory calculations need to be tracked. Skywalking can customize the tracking scope through annotations.

1: Introduce dependencies

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

2: the burial site

@Controller @Slf4j public class UserController { ... @requestMapping ("findAll") @responseBody // Buried point, not specified operationName, default set to "class name". Method name "@trace (operationName =" findall-operationName ") public List<Person> findAll() {// Obtain traceId log.info(" >>>>> Trace  id is {} ", TraceContext.traceId()); // Tag activespan. tag(" This is the tag ", "tag value "); // Info event activespan. info(" This is an info log "); // debug event activespan.debug (" This is a debug log "+ tracecontext.traceid () +" <- preceded by id "); List<Person> all = null; try { all = personService.findAll(); } catch (Throwable t) {// error event activespan. error(t); } return all; }Copy the code

Api description

  • TraceId TraceContext# traceId
  • ActiveSpan# tag labeling
  • ActiveSpan#debug debug log events
  • ActiveSpan#info info log event
  • ActiveSpan# error error exception

3: Final effect