分布式服务 Trace - 慢请求的排查思路

通过系统监控发现，某个核心服务如支付下单服务在高峰期时出现少量的慢请求，有用户向客服反馈在APP上支付下单时出现等待时间比较长的情况。由于下单服务调用了多个RPC或API服务，短时间内很难判断具体是调用链中的哪个服务出现了问题。

在原来单体服务的情况下，简单方法就是打印处理流程的各个步骤的耗时情况日志，然后去日志中分析耗时情况，找到引起慢请求的那个或多个服务，进行针对性的优化。
但是这种方案下，如果系统请求量稍微高点，就会出现多个日志穿插打印，很难一眼分辨出哪些是来自同一个请求，这时候需要一个标记来对同一个请求下的日志进行区分，这个标记可以叫做requestId，在请求进入的时候生成，放在线程上下文中，在需要的时候可以获取这个requestId并打印至日志中。
现在已经可以通过日志分析出导致慢请求的具体原因了，比如，发现是下单操作时数据库查询慢导致的请求耗时增加，然后对数据库进行了优化，比如索引，这个问题最终得到解决。

可是没过多久，商品相关的服务又出现了请求缓慢的问题，又通过在代码中增加日志的方式来排查问题，很快，你会发现这种排查方式麻烦耗时，每次出现问题需要临时增加日志排查，不仅需要重新发布版本，而且排查时间也比较长。

其实，一个接口出现响应时间慢的问题，大概率是出现在跨网络调用上，如数据库查询、依赖的第三方服务、缓存服务等，我们需要在这些外部调用的地方，统一的做耗时统计并进行上报。

AOP是比较适合这类场景的，在不修改源代码的情况下，对处理过程进行拦截处理，我们就可以在调用外部服务时进行耗时统计，并上报至日志。

切面编程分成两类：

由于只是生成用于排查问题的追踪日志，应该尽量减少对接口性能的影响，推荐使用静态代理的方式。

需要注意的点：

日志上报需要一个集中存储，如Elasticsearch，如果还是打印到服务器上的文本文件中，找日志又是一个问题。
如果服务的请求量很大，一次完整的请求可能会多达十几次的外部请求，假设系统的QPS是1000，那么一秒钟就会产生上万条日志，排查问题并不需要这么多的日志，需要对日志进行采样过滤，简单的方式就是使用requestId，假设采集20%的日志，那么就是requestId%10==0的请求进行打印。
基于尽可能减少日志打印对接口性能影响的出发点，日志需要采用异步的方式写入消息队列，也可以在程序内部实现一个队里，然后由专门的消息处理程序或者处理线程把日志消息进行上报。
最好是在配置中心配置有日志相关的设置，比如日志打印开关、日志采样数量等，这样就会更加灵活可控。

以上的改造可以解决了日志获取困难、多个请求的日志难以区分、全量日志打印的问题，但是在分布式服务的环境下，一次完整请求下的服务调用顺序是难以区分的，比如，你知道下单接口请求了A，B，C三个服务，却不知道请求的顺序是什么（异步请求前提下）。

现在需要其他标识去区分所依赖外部服务的调用顺序，假设这个调用顺序用字段orderId进行标识，那么就是requestId + orderId 这两个数据维度来记录服务之间的调用关系，也就是使用 requestId 区分单次请求，用 orderId 记录每一次依赖的外部调用。

比如，你的请求从用户端过来，先到达 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，以此类推。