高并发系统设计：横跨几十个分布式组件的慢请求如何排查

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

问题：

某个接口的响应慢怎么解决

思路

最简单的思路是：打印每一个步骤的耗时情况，然后搜索关键词来查看每个步骤的耗时情况，通过比较这些耗时的操作，然后再看这个步骤要如何优化：

long start = System.currentTimeMillis();
processA();
Logs.info("process A cost " + (System.currentTimeMillis() - start));// 打印 A 步骤
start = System.currentTimeMillis();
processB();
Logs.info("process B cost " + (System.currentTimeMillis() - start));// 打印 B  步骤
start = System.currentTimeMillis();
processC();
Logs.info("process C cost " + (System.currentTimeMillis() - start));// 打印 C  步骤

问题是：由于同时会有多个下单请求并行处理，所以，这些下单请求的每个步骤的耗时日志，是相互穿插打印的。你无法知道这些日志，哪些是来自同一个请求，也就不能直观的看到，某一次请求耗时最多的步骤是哪一步了。那么，如何把单次请求，每个步骤的耗时情况串起来呢？

解决方法：给同一个请求的每一行增加日志，增加一个相同的标记。这样，只要拿到这个标记就可以查找到这个请求链路上，所有步骤的耗时了，我们把这个标记叫做requestId。我们可以在程序的入口处生成一个requestId，然后把它放在线程的上下文中，这样就可以在需要时，随时从线程上下文中获取到requestId

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 = System.currentTimeMillis();
processB();
Logs.info("rid : " + tl.get() + ", process B cost " + (System.currentTimeMillis
start = System.currentTimeMillis();
processC();
Logs.info("rid : " + tl.get() + ", process C cost " + (System.currentTimeMillis

解决了这个问题之后还是有问题：每次排查一个接口就需要增加日志、重启服务，这并不是一个好的办法

解决

经验上来看，一个接口响应时间慢，一般是出现在跨网络的调用上，比如说请求数据库、缓存或者依赖的第三方服务。所以，我们只需要针对这些调用的客户端类，做切面编程(AOP)，通过插入一些代码打印他们的耗时就好了

切面编码是面向对象编程的一种延伸，可以在不修改源代码的前提下，给应用程序添加功能，比如说鉴权，打印日志等等。

就像开发人员在向代码仓库提交代码之后，需要对代码编译、构建、执行单元测试用例，以保证提交的代码是没有问题的。但是，如果每次/每个人提交代码都要做这么多事情，无疑会造成很大的负担，所以可以配置可以持续集成的流程，在提交代码之后，自动完成这些操作，这个持续集成的流程就可以认为是一个切面。

一般来说，切面编程的实现分为两类：

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

这两者有什么差别呢？

• 以Java为例，源代码Java文件先被Java编译器，编译成Class文件，然后Java虚拟机将Class装载进来之后，进行必要的验证和初始化之后就可以运行了。
• 静态代理是在编译器插入代码，增加了编译的时间，给你的直观感觉就是启动的时间变长了，但是一旦在编译期插入代码之后，在运行期间基本对性能就没有影响
• 而动态代理不会去修改生成的class文件，而是会在运行期间生成一个代理对象，这个代理对象对源对象做了字节码增强，来完成切面所要执行的操作。由于在运行期间需要生成代理对象，所以动态代理的性能要比静态代理差。

我们做切面的原因，是想生成一些调试的日志，所以我们期望尽量减少对原先接口性能的影响。因此，推荐使用静态代理实现切面编程。

使用 AspectJ 做切面的简单代码实现就像下面这样：

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

可以考虑对请求做采样。采样的方式也简单，比如你想采样 10% 的日志，那么你可以只打印“requestId%10==0”的请求。

有了这些日志之后，当给你一个requestID的时候，你发现自己并不能确认这个请求到了哪一台服务器上，所以你不得不登录所有服务器，去搜索这个requestId才能定位请求。这样无疑会增加问题的排查时间。

解决思路：把日志不打印到本地文件中，而是发送到消息队列里，再由消息处理程序写入到集中存储中，比如 Elasticsearch。这样，你在排查问题的时候，只需要拿着 requestId 到 Elasticsearch 中查找相关的记录就好了

总结：

为了排查单次请求响应时间长的原因，主要做了下面这些事情：

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

如何来做分布式trace

在一体化架构中，单次请求的所有耗时日志，都被记录在一台服务器上，而在微服务的场景下，单次请求可能跨越多个RPC服务，这就造成了单次的请求的日志会分布在多个服务器上。

当然，也可以通过requestId将多个服务器上的日志串起来，但是仅仅依赖requestId很难表达服务之间的调用关系，也就是从日志中，无法了解服务之间是谁在调用谁。因此，我们采用traceId和spanId这两个数据维度来记录服务之间的调用关系（这里traceId 就是 requestId）也就是使用 traceId 串起单次请求，用 spanId 记录每一次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，以此类推。
  
  通过这种方式，我们可以在日志中，清晰地看出服务的调用关系是如何的，方便在后续计算中调整日志顺序，打印出完整的调用链路。

那么 spanId 是何时生成的，又是如何传递的呢？

• 首先，A服务在发起RPC请求服务B前，先从线程上下文中获取当前的traceId和spanId，然后，依据上面的逻辑生成本次RPC调用的spanId，再将spanId和traceId序列化之后，装配到请求体中，发送给服务方B
• 服务方B获取请求后，从请求体中反序列化出 spanId 和 traceId，同时设置到线程上下文中，以便给下次 RPC 调用使用。在服务 B 调用完成返回响应前，计算出服务 B 的执行时间发送给消息队列。
• 当然，在服务 B 中，你依然可以使用切面编程的方式，得到所有调用的数据库、缓存、HTTP 服务的响应时间，只是在发送给消息队列的时候，要加上当前线程上下文中的spanId 和 traceId。
• 这样，无论是数据库等资源的响应时间，还是 RPC 服务的响应时间就都汇总到了消息队列中，在经过一些处理之后，最终被写入到 Elasticsearch 中以便查询

还有一个问题是性能问题，也就是引入了分布式追踪中间件导致对磁盘IO和网络IO的影响。建议：

• 如果使用自研分布式trace中间件，那么一定要提供一个开关，方便在线上随时将日志打印关闭
• 如果使用开源的组件，可以开始设置一个较低的日志采样率，关系系统性能情况再调整到一个合适的数值

小结

在排查单次慢请求中哪一步是瓶颈时注意注意：

• 服务的追踪的需求主要有两点，一是对代码要无侵入，可以使用切面编程来解决；二是性能要低损耗，建议采用静态代理+日志采样，尽量减少追踪日志对系统性能的影响
• 无论是单体系统还是服务化架构，无论是服务追踪还是业务问题排查，都需要在日志中增加 requestId，这样可以将你的日志串起来，给你呈现一个完整的问题场景。如果requestId 可以在客户端上生成，在请求业务接口的时候传递给服务端，那么就可以把客户端的日志体系也整合进来，对于问题的排查帮助更大。

其实，分布式追踪系统不是一项新的技术，而是若干已有技术的整合，在实现上并不复杂，却能够实现跨进程调用链展示、服务依赖。所以，在微服务化过程中，它是一个必选项，无论是采用开源还是自研的方案，都应该在微服务化完成之前，尽快让它发挥应有的价值。