通过日志服务调试分布式系统

为了解决分布式系统开发过程中调试和分析性能的问题，在过去阿里云产品的开发调试过程中，我们开发了Tracer工具。Tracer主要用来解决分布式系统执行过程关联问题，它的基本原理如下：

用户在关键程序的入口埋点以日志方式输出时间、Trace ID、上下文等信息。当用户请求经过埋点函数时，输出日志。通过以上步骤，我们就能通过关联同样的Trace ID来记录一个请求生命周期内访问多个进程的情况。

当携带Trace ID的请求每一次执行到这个宏，会留下这样一条日志：

[2013-07-13 10:28:12.147635] [DEBUG] [26064]  __TRACE_ID__:661353951201  __item__:[Class:Function]_start__

当退出这个宏所在的作用域时，再打印出这样一行日志：

[2013-07-13 10:28:12.772518]    [DEBUG] [26064]  __TRACE_ID__:661353951201    __item__:[Class:Function]_end__  request_id:1734117   user_id:124

这两行日志包含了起止时间、延时、上下文信息。通过把整个集群中相同的Trace ID串起来，我们就能拿到整个请求在不同机器/服务中的运行轨迹了。

在实现Tracer的过程中，我们可以看到系统需要有三个过程：

• 在程序中埋点，打印出日志
• 收集日志到日志服务

• 分析profiling日志

  Tracer的信息以日志的形式保存在本地磁盘上之后。如果分析一台机器的日志，只需要在上边跑个脚本进行分析。但分布式系统的困难在于，日志散落在不同的机器的不同模块目录中。可见除了在程序中传递Trace ID，输出到日志之外，很重要的一块内容是如何实时地把上千台机器的不同进程打印出的这些日志收集起来做分析。

本文为您介绍日志服务如何为Tracer服务的。

Tracer如何使用SLS收集和分析日志

Tracer日志的需求总结起来有两点：

• 日志的实时收集：
• 能够从多台机器上实时的收集日志并且发送到服务端

在收集过程中做到实时、容错，包括文件系统错误、网络错误

在集群规模上，能够做到可扩展，针对不同规模的集群，都能满足以上需求

日志的关联、分析和查询：

• 纵向分析：比如查看一次调用的整体过程，由Tracer日志构建出Call graph，通过分析Call graph，从宏观角度查看性能损耗在哪个函数上，进而定位到性能瓶颈函数。在纵向分析中，最关键的一点是如何通过Trace ID把一次调用的上下文组织起来。

• 横向分析：比如从横向角度，对于一个函数的性能做横向比较，查找出所有调用中latency top20最差的调用。查看单个函数的耗时情况，比如一个函数的latency随着时间变化的趋势。
  统计分析：统计一天内所有函数的调用次数、平均延时、最大延时，并且最终通过报表展示结果。

  针对以上需求，日志服务天然地提供了日志的基础服务以及完整的restful API，可以把整个集群的机器上的日志收集、处理、存储，展示出程序完整的Call graph，实现分析程序性能的目的。
  

上图是Tracer使用简单日志服务的结构图：Tracer产生的日志由安装在机器上的Logtail实时收集写到日志服务。Logtail实时采集日志文件增量日志。Logtail提供了断点续传功能保证数据可靠性传输，并且日志服务为logtail提供配置托管，管理整个集群的配置，最大限度的方便用户管理logtail和动态增删配置。

在收集完日志后，用户通过SLS提供的日志存储/查询功能对Tracer的需求进行设置，最后通过Restful API取得数据，进行业务展示。以下是一些代表性的场景：

1：纵向分析。通过分析一次调用的call graph，定性分析程序的热点在哪里。例如下图OlsIndexJoinServer：HandleRequest这次调用共消耗3.2s。其中AsyncGetLog这个函数消耗了全部时间的99.82%。可以认为这个函数是一个热点，是性能优化的方向。这种通过查看Call graph来分析问题的方法适合于人工分析。

图 Tracer Call graph

那么上图的Call graph是怎么构造的呢？在上文提到，Tracer日志中有一个字段叫Trace ID，这个ID在整个调用期间保持不变和唯一性。通过这个Trace ID，可以查找到本次调用的所有日志。日志服务提供了索引功能，为所有的日志建立索引，指定关键字就可以查找到命中的日志。以Trace ID作为关键字，可以很方便的找出这次请求的所有Trace log，这些日志中包含了起始时间，按照时间顺序把日志组织起来，就能够形成Call graph。

图 通过Trace ID查找一次调用的所有Tracer日志

日志服务索引功能支持查询多个关键字，以及and or not等语法结构。以下图为例，查找OlsIndexMaster::HandleRequest这个函数相关的所有日志，只需要以“OlsIndexMaster HandleRequest”作为关键字，指定时间范围，便可以找到这个函数打印出来的所有日志。对于索引数据的查询提供了两种形式的结果：第一种是命中日志条数在时间维度上的分布，如下图的蓝色区域；第二种是提供命中的日志。

图 多关键字查询结果

2：横向分析。以下图为例，通过下游接入一个spark系统，配置一个实时规则avg，实现查看ReadOtsLog这个函数的latency的平均值在时间维度上的变化曲线。

图 统计latency平均值

或者统计一段时间内某个函数性能top20最差的几次调用耗时：

一天内latency最大的几次Tracer Id