Spring Cloud构建微服务架构:分布式服务跟踪(跟踪原理)【Dalston版】

通过上一篇《分布式服务跟踪(入门)》的例子,我们已经通过Spring Cloud Sleuth往微服务应用中添加了实现分布式跟踪具备的基本要素。下面通过本文来详细说说实现分布式服务跟踪的一些要点。

分布式系统中的服务跟踪在理论上并不复杂,它主要包括下面两个关键点:

  • 为了实现请求跟踪,当请求发送到分布式系统的入口端点时,只需要服务跟踪框架为该请求创建一个唯一的跟踪标识,同时在分布式系统内部流转的时候,框架始终保持传递该唯一标识,直到返回给请求方为止,这个唯一标识就是前文中提到的Trace ID。通过Trace ID的记录,我们就能将所有请求过程日志关联起来。
  • 为了统计各处理单元的时间延迟,当请求达到各个服务组件时,或是处理逻辑到达某个状态时,也通过一个唯一标识来标记它的开始、具体过程以及结束,该标识就是我们前文中提到的Span ID,对于每个Span来说,它必须有开始和结束两个节点,通过记录开始Span和结束Span的时间戳,就能统计出该Span的时间延迟,除了时间戳记录之外,它还可以包含一些其他元数据,比如:事件名称、请求信息等。

在快速入门示例中,我们轻松实现了日志级别的跟踪信息接入,这完全归功于spring-cloud-starter-sleuth组件的实现。在Spring Boot应用中,通过在工程中引入spring-cloud-starter-sleuth依赖之后, 它会自动的为当前应用构建起各通信通道的跟踪机制,比如:

  • 通过诸如RabbitMQ、Kafka(或者其他任何Spring Cloud Stream绑定器实现的消息中间件)传递的请求
  • 通过Zuul代理传递的请求
  • 通过RestTemplate发起的请求

在快速入门示例中,由于trace-1trace-2发起的请求是通过RestTemplate实现的,所以spring-cloud-starter-sleuth组件会对该请求进行处理,在发送到trace-2之前sleuth会为在该请求的Header中增加实现跟踪需要的重要信息,主要有下面这几个(更多关于头信息的定义我们可以通过查看org.springframework.cloud.sleuth.Span的源码获取):

  • X-B3-TraceId:一条请求链路(Trace)的唯一标识,必须值
  • X-B3-SpanId:一个工作单元(Span)的唯一标识,必须值
  • X-B3-ParentSpanId::标识当前工作单元所属的上一个工作单元,Root Span(请求链路的第一个工作单元)的该值为空
  • X-B3-Sampled:是否被抽样输出的标志,1表示需要被输出,0表示不需要被输出
  • X-Span-Name:工作单元的名称

我们可以通过对trace-2的实现做一些修改来输出这些头部信息,具体如下:

@RequestMapping(value = "/trace-2", method = RequestMethod.GET)
public String trace(HttpServletRequest request) {
    logger.info("===<call trace-2, TraceId={}, SpanId={}>===",
            request.getHeader("X-B3-TraceId"), request.getHeader("X-B3-SpanId"));
    return "Trace";
}

通过上面的改造,我们再运行快速入门的示例内容,并发起对trace-1的接口访问,我们可以得到如下输出内容。其中在trace-2的控制台中,输出了当前正在处理的TraceIDSpanId信息。

-- trace-1
INFO [trace-1,a6e9175ffd5d2c88,8524f519b8a9e399,true] 10532 --- [nio-9101-exec-2] icationEnhancerBySpringCGLIB27aa9624 : ===<call trace-1>===

-- trace-2
INFO [trace-2,a6e9175ffd5d2c88,ce60dcf1e2ed918f,true] 1208 --- [nio-9102-exec-3] icationEnhancerBySpringCGLIBa7d84797 : ===<call trace-2, TraceId=a6e9175ffd5d2c88, SpanId=be4949ec115e554e>===

为了更直观的观察跟踪信息,我们还可以在application.properties中增加下面的配置:

logging.level.org.springframework.web.servlet.DispatcherServlet=DEBUG

通过将Spring MVC的请求分发日志级别调整为DEBUG级别,我们可以看到更多跟踪信息:

-- trace-1
2016-11-27 09:26:52.663 DEBUG [trace-1,a6e9175ffd5d2c88,a6e9175ffd5d2c88,true] 10532 --- [nio-9101-exec-2] o.s.web.servlet.DispatcherServlet        : DispatcherServlet with name 'dispatcherServlet' processing GET request for [/trace-1]
2016-11-27 09:26:52.666 DEBUG [trace-1,a6e9175ffd5d2c88,a6e9175ffd5d2c88,true] 10532 --- [nio-9101-exec-2] o.s.web.servlet.DispatcherServlet        : Last-Modified value for [/trace-1] is: -1
2016-11-27 09:26:52.685 DEBUG [trace-1,a6e9175ffd5d2c88,8524f519b8a9e399,true] 10532 --- [nio-9101-exec-2] o.s.web.servlet.DispatcherServlet        : Null ModelAndView returned to DispatcherServlet with name 'dispatcherServlet': assuming HandlerAdapter completed request handling
2016-11-27 09:26:52.685 DEBUG [trace-1,a6e9175ffd5d2c88,a6e9175ffd5d2c88,true] 10532 --- [nio-9101-exec-2] o.s.web.servlet.DispatcherServlet        : Successfully completed request

-- trace-2
2016-11-27 09:26:52.673 DEBUG [trace-2,a6e9175ffd5d2c88,be4949ec115e554e,true] 1208 --- [nio-9102-exec-3] o.s.web.servlet.DispatcherServlet        : DispatcherServlet with name 'dispatcherServlet' processing GET request for [/trace-2]
2016-11-27 09:26:52.679 DEBUG [trace-2,a6e9175ffd5d2c88,be4949ec115e554e,true] 1208 --- [nio-9102-exec-3] o.s.web.servlet.DispatcherServlet        : Last-Modified value for [/trace-2] is: -1
2016-11-27 09:26:52.682 DEBUG [trace-2,a6e9175ffd5d2c88,ce60dcf1e2ed918f,true] 1208 --- [nio-9102-exec-3] o.s.web.servlet.DispatcherServlet        : Null ModelAndView returned to DispatcherServlet with name 'dispatcherServlet': assuming HandlerAdapter completed request handling
2016-11-27 09:26:52.683 DEBUG [trace-2,a6e9175ffd5d2c88,be4949ec115e554e,true] 1208 --- [nio-9102-exec-3] o.s.web.servlet.DispatcherServlet        : Successfully completed request

原文地址:http://blog.didispace.com/spring-cloud-starter-dalston-8-2/

完整示例:

读者可以根据喜好选择下面的两个仓库中查看trace-1trace-2两个项目:

如果您对这些感兴趣,欢迎star、follow、收藏、转发给予支持!

本文内容部分节选自我的《Spring Cloud微服务实战》,但对依赖的Spring Boot和Spring Cloud版本做了升级。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 216,324评论 6 498
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 92,356评论 3 392
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 162,328评论 0 353
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 58,147评论 1 292
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 67,160评论 6 388
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 51,115评论 1 296
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 40,025评论 3 417
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 38,867评论 0 274
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 45,307评论 1 310
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,528评论 2 332
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,688评论 1 348
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 35,409评论 5 343
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 41,001评论 3 325
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,657评论 0 22
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,811评论 1 268
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 47,685评论 2 368
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,573评论 2 353

推荐阅读更多精彩内容