高并发系统设计学习笔记(二十三) 分布式系统排查慢请求

目录

一、场景分析

二、一体化架构中的慢请求排查如何做

三、如何来做分布式Trace

---

一、场景分析

垂直电商系统在引入RPC框架和注册中心之后已经完成基本的服务化拆分了，系统架构变成了下面的结构。经过了服务化拆分之后，服务的可扩展性增强了很多，可以通过横向扩展服务节点的方式平滑地扩容了，对于应对峰值流量也更有信心了。

 但是这时出现了问题： 你通过监控发现，系统的核心下单接口在晚高峰的时候，会有少量的慢请求，用户也投诉在APP上下单时，等待的时间比较长。而下单的过程可能会调用多个RPC服务或者使用多个资源，一时之间，你很难快速判断究竟是哪个服务或者资源出了问题，从而导致整体流程变慢，想办法如何排查这个问题。

---

二、一体化架构中的慢请求排查如何做

最简单的思路是：打印下单操作的每一个步骤的耗时情况，然后通过比较这些耗时的数据，找到延迟最高的一步，然后再来看看这个步骤要如何优化。如果有必要的话，你还需要针对步骤中的子步骤，再增加日志来继续排查

String requestId = UUID.randomUUID().toString();
ThreadLocal<String> tl = new ThreadLocal<String>(){
    @Override
    protected String initialValue() {
        return requestId;
    }
}; //requestId存储在线程上下文中
long start = System.currentTimeMillis();
processA();
Logs.info("rid : " + tl.get() + ", process A cost " + (System.currentTimeMillis() - start)); // 日志中增加requestId
start = System.currentTimeMillis();
processB();
Logs.info("rid : " + tl.get() + ", process B cost " + (System.currentTimeMillis() - start));
start = System.currentTimeMillis();
processC();
Logs.info("rid : " + tl.get() + ", process C cost " + (System.currentTimeMillis() - start));

切面编程（AOP）是面向对象编程的一种延伸，可以在不修改源代码的前提下给应用程序添加功能，比如说鉴权、打印日志等等。一般来说，切面编程的实现分为两类：

• 一类是静态代理，典型的代表是AspectJ，它的特点是在编译期做切面代码注入；
• 另一类是动态代理，典型的代表是Spring AOP，它的特点是在运行期做切面代码注入

@Aspect
public class Tracer {
    @Around(value = "execution(public methodsig)", argNames = "pjp") //execution内替换要做切面的方法签名
    public Object trace(ProceedingJoinPoint pjp) throws Throwable {
        TraceContext traceCtx = TraceContext.get(); //获取追踪上下文，上下文的初始化可以在程序入口处
        String requestId = reqCtx.getRequestId(); //获取requestId
        String sig = pjp.getSignature().toShortString(); //获取方法签名
        boolean isSuccessful = false;
        String errorMsg = "";
        Object result = null;
        long start = System.currentTimeMillis();
        try {
            result = pjp.proceed();
            isSuccessful = true;
            return result;
        } catch (Throwable t) {
            isSuccessful = false;
            errorMsg = t.getMessage();
            return result;
        } finally {
            long elapseTime = System.currentTimeMillis() - start;
            Logs.info("rid : " + requestId + ", start time: " + start + ", elapseTime: " + elapseTime + ", sig: " + sig + ", isSuccessful: " + isSuccessful + ", errorMsg: " + errorMsg  );
        }
    }
}

你就在你的系统的每个接口中打印出了所有访问数据库、缓存、外部接口的耗时情况，一次请求可能要打印十几条日志，如果你的电商系统的QPS是10000的话，就是每秒钟会产生十几万条日志，对于磁盘I/O的负载是巨大的，那么这时，你就要考虑如何减少日志的数量。 

• 在记录打点日志时，我们使用requestId将日志串起来，这样方便比较一次请求中的多个步骤的耗时情况；
• 我们使用静态代理的方式做切面编程，避免在业务代码中，加入大量打印耗时的日志的代码，减少了对于代码的侵入性，同时编译期的代码注入可以减少；
• 我们增加了日志采样率，避免全量日志的打印；
• 最后为了避免在排查问题时需要到多台服务器上搜索日志，我们使用消息队列将日志集中起来放在了Elasticsearch中

---

三、如何来做分布式Trace

在微服务的场景下，单次请求可能跨越多个RPC服务，这就造成了单次的请求的日志会分布在多个服务器上。比如，你的请求从用户端过来，先到达A服务，A服务会分别调用B和C服务，B服务又会调用D和E服务

• 用户到A服务之后会初始化一个traceId为100，spanId为1；
• A服务调用B服务时，traceId不变，而spanId用1.1标识代表上一级的spanId是1，这一级的调用次序是1；
• A调用C服务时，traceId依然不变，spanId则变为了1.2，代表上一级的spanId还是1，而调用次序则变成了2，以此类推