[译]OpenTracing之旅

[译]OpenTracing之旅

原文链接：https://medium.com/opentracing/take-opentracing-for-a-hotrod-ride-f6e3141f7941

OpenTracing是一个新的开放标准，适用于应用和开源软件包的分布式链路追踪和监控。本文将借助一个demo带你探索OpenTracing的特性及功能，一步步向你展示如何在实践中应用OpenTracing概念来监控基于微服务的体系结构并进行性能问题的根因分析；本文还强调了OpenTracing的关键特性：厂商无关，平台无关，OpenTracing允许自由的选用其他开源框架（例如RPC框架）实现分布式跟踪。在Demo源码中的RPC调用中并没有显式的使用OpenTracing API，因为开源社区的一些免费工具可以自动帮我们完成。

必要条件

1. 该Demo使用Go实现，所以需要搭建好Go的工具链
2. 推荐使用Docker部署Jaeger后端，所以需要已安装Docker
3. 完整的Demo源码可在Github获取：https://github.com/uber/jaeger/tree/master/examples/hotrod，请参阅README文件中有关如何下载和运行Jaeger后端和本Demo的说明。

议程

1. 介绍本Demo程序及其特性

2. 借助Jaeger UI理解Demo程序的架构和数据流

3. 对比普通服务日志和OpenTracing中的日志

4. 在调用图中识别延迟和错误的来源

5. 通过“baggage” 在链路中传递调用链顶端的信息，实现调用链路耗时的统计

6. 无需任何其他工具即可获取RPC远端的指标

7. 查看有关如何实现上述功能的代码示例。其中大部分功能都无需繁琐的手动操作，因为我们使用的开源框架已经集成了OpenTracing

启动Jaeger

下面我们将会使用Jaeger，一个开源的分布式追踪系统，来采集并查看分析应用的行为。让我们使用all-in-one的Docker镜像来启动Jaeger后端服务：

$ docker run -d --name jaeger \
  -e COLLECTOR_ZIPKIN_HTTP_PORT=9411 \
  -p 5775:5775/udp \
  -p 6831:6831/udp \
  -p 6832:6832/udp \
  -p 5778:5778 \
  -p 16686:16686 \
  -p 14268:14268 \
  -p 14250:14250 \
  -p 9411:9411 \
  jaegertracing/all-in-one:1.18

容器启动后，我们可以就在浏览器访问Jaeger UI了：http://127.0.0.1:16686/。

容器里的Jaeger后端使用的是内存存储引擎，首次启动时是空的，所以现在我们在Jaeger UI上暂时还不能查看具体的trace信息，让我们启动demo程序生成一些trace信息吧。

启动Demo程序 HotROD

HotROD是一个网约车应用demo程序，让我们下载并启动它（请参考最新的README指导）:

git clone git@github.com:jaegertracing/jaeger.git jaeger
cd jaeger/examples/hotrod
go run ./main.go all

注：从Jaeger项目的1.3版本开始，引入了HotROD 程序的Docker镜像（请参阅README），以快速启动并测试该程序，但在本文中我们会修改一些源代码，所以我们使用编译源码启动。

这里的all命令通知程序在一个二进制文件中启动所有的微服务。我们可以在标准输出中打印的日志中看到这些微服务已经启动并监听着不同的端口：

2017–05–03T23:53:19.693–0400 INFO cmd/all.go:31 Starting all services
2017–05–03T23:53:19.696–0400 INFO log/logger.go:43 Starting {
   “service”: “route”, “address”: “http://127.0.0.1:8083"}
2017–05–03T23:53:19.696–0400 INFO log/logger.go:43 Starting {“service”: “frontend”, “address”: “http://127.0.0.1:8080"}
2017–05–03T23:53:19.697–0400 INFO log/logger.go:43 Starting {
   “service”: “customer”, “address”: “http://127.0.0.1:8081"}
2017–05–03T23:53:19.697–0400 INFO log/logger.go:43 TChannel listening {
   “service”: “driver”, “hostPort”: “127.0.0.1:8082”}

让我们打开服务的主入口：http://127.0.0.1:8080/

界面中有四个按钮分别代表一位乘客，点击其中一个即可为该乘客发起约车请求，请求到达后端，经过计算后端会返回接单司机的车牌号及预计到达时间。

界面上会显示一些调试信息：

1. 左上角有一个web client id: 9323，它是由JavaScript UI随机生成的session ID，如果刷新页面，会生成一个不同的session ID
2. 在车辆信息的一行中，req: 9323–1代表请求ID，由Session ID和一个序列号组成，会被发送至后端
3. 最后，latency: 782ms是有JavaScript UI测量的请求响应时间

以上这些附加信息不会影响应用程序的行为，但对我们深入了解背后的机制很有帮助。

Demo架构

现在我们已经清楚了整个应用的功能，我们可能想知道它的架构情况。毕竟，也许我们在日志中看到的所有那些服务只是用于展示，而整个应用程序仅仅是一个JavaScript前端。在不向开发人员索要设计文档的情况下，Jaeger可以通过观察服务之间的交互来自动构建架构图，这听起来不是很好吗？这正是Jaeger的能力！我们执行约车的请求已经提供了足够的数据，让我们转到“依赖关系”页面，然后点击DAG标签：

事实证明，HotROD的单个二进制文件实际上正在运行四个微服务，并且很显然，还有两个存储服务。其实，这两个存储接点并不是真实存在的，它们是由应用的内部组件模拟的，但是前四个微服务的确是真实存在的，我们在前面已经看到了这四个微服务监听地址的日志。frontend服务由Javascript UI组成，并且负责向其他三个服务发起RPC调用。上图也表明了一次约车请求，各个服务间的调用次数，比如，route服务被调用了10次，还有对redis的14次调用。

Demo数据流

我们已经了解到HotROD应用由四个微服务构成，那么请求在各服务间究竟是怎样流转的呢？是时候查看以下真正的追踪信息了。我们回到Jaeger UI的搜索页面，在Find Traces标题下，有个Services的下拉菜单包含我们刚才看到的那些微服务。我们知道frontend服务是我们的根服务，所以我们这里我们选择frontend并点击Find Traces。

Jaeger系统已经发现了一条追踪信息和一些相关的元信息，比如这条追踪链上涉及服务的名字、各服务向Jaeger上报的span的总数。如上图标题栏所示，整个调用链路的顶层根入口是HTTP GET /dispatch，在右侧我们可以看出整个调用的耗时为774.85ms；这个数据比我们之前在HotROD UI上看到的小一点点，这是因为HotROD UI上是由JavaScript测量的，7.15ms的误差是由http连接建立及http传输的耗时引起的。下面让我们点击并查看这条追踪信息：

上面的时间线展示了一条包含多个嵌套span的追踪信息的典型视图，这里的sapn表示某服务内的一个工作单元。顶层span有时也称为root span，代表从Javascript UI到frontend的HTTP请求，期间，frontend又调用了customer，后者又调用了MySQL。span的宽度与操作的耗时成正比，这里的操作可能是内部的计算或者下游的调用。

从上图中，我们可以清晰地看出应用服务如何处理一个请求：

1. frontend服务收到一条外部的HTTP GET请求，请求路径为/dispatch
2. frontend服务向customer服务发起一条HTTP GET请求，请求路径为/customer
3. customer服务调用MySQL执行了一条SQL SELECT语句，处理结果被返回至frontend服务
4. frontend服务向driver服务发起了RPC调用（Driver::findNearest），在没有深挖这条trace信息前，我们还看不出使用的是哪一个RPC框架，但是我们可以猜测不是HTTP（实际上是TChannel）
5. driver服务向redis发起了一系列的请求，其中一些请求被使用粉色背景高亮，表明是失败
6. 随后frontend向route服务发起一条HTTP GET请求，请求路径为/route
7. 最后，frontend向外部调用者（浏览器）返回处理结果

如果我们点击上图时间线中的任一span，它会展开并显示详细信息，包括span tags、process tags和logs。让我们点击一个失败Redis请求的span：

我们可以看到tags信息中有一条error=true，所以这个span被高亮；在Logs下还可以看到一些错误信息的原始声明——“redis timeout”，我们也可以看到driver服务尝试从Redis获取的driver_id。

情景化日志

现在我们已经对整个应用的功能有了充分的了解，除了底层的运作机制，比如，为什么frontend服务要调用customer服务的/customer接口？当然，我们可以查看源代码，但是我们这次想从应用监控的角度去分析，可取的一个方向是查看这个应用输出的日志。

从这些繁杂的日志中找出应用的执行逻辑是非常困难的，而且通常我们查看日志时只想查看某一次调用的日志，想象一下大量并发的请求进入系统，在这种情况下日志凌乱到几乎没用。所以唱我们另辟蹊跷，看一下追踪系统收集的日志，点击root span展开详情并展开它的日志：