SpringCloud/spring-cloud-sleuth
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Updated README.md

Browse Source
This commit is contained in:
Marcin Grzejszczak
2016-03-03 16:29:44 +01:00
parent d6b623fdf7
commit 6e3efa8fb3
1 changed files with 127 additions and 12 deletions
Download Patch File Download Diff File Expand all files Collapse all files

139
README.adoc
View File

@@ -10,13 +10,100 @@ Spring Cloud Sleuth implements a distributed tracing solution for http://cloud.s
Spring Cloud Sleuth borrows http://research.google.com/pubs/pub36356.html[Dapper's] terminology.
*Span:* The basic unit of work. For example, sending an RPC is a new span, as is sending a response to an RPC. Span's are identified by a unique 64-bit ID for the span and another 64-bit ID for the trace the span is a part of. Spans also have other data, such as descriptions, timestamped events, key-value annotations (tags), the ID of the span that caused them, and process ID's (normally IP address).
*Span:* The basic unit of work. For example, sending an RPC is a new span, as is sending a response to an
RPC. Span's are identified by a unique 64-bit ID for the span and another 64-bit ID for the trace the span
is a part of. Spans also have other data, such as descriptions, timestamped events, key-value
annotations (tags), the ID of the span that caused them, and process ID's (normally IP address).
Spans are started and stopped, and they keep track of their timing information. Once you create a span, you must stop it at some point in the future.
Spans are started and stopped, and they keep track of their timing information. Once you create a
span, you must stop it at some point in the future.
*Trace:* A set of spans forming a tree-like structure. For example, if you are running a distributed big-data store, a trace might be formed by a put request.
*Trace:* A set of spans forming a tree-like structure. For example, if you are running a distributed
big-data store, a trace might be formed by a put request.
*Annotation:* is used to record existence of an event in time. Some of the core annotations used to define
the start and stop of a request are:
- *cs* - Client Sent - The client has made a request. This annotation depicts the start of the span.
- *sr* - Server Received - The server side got the request and will start processing it.
If one subtracts the cs timestamp from this timestamp one will receive the network latency.
- *ss* - Server Sent - Annotated upon completion of request processing (when the response
got sent back to the client). If one subtracts the sr timestamp from this timestamp one
will receive the time needed by the server side to process the request.
- *cr* - Client Received - Signifies the end of the span. The client has successfully received the
response from the server side. If one subtracts the cs timestamp from this timestamp one
will receive the whole time needed by the client to receive the response from the server.
Visualization of what *Span* and *Trace* will look in a system together with the Zipkin annotations:
image::trace-id.png[Trace Info propagation]
Each color of a note signifies a span (7 spans - from *A* to *G*). If you have such information in the note:
[source]
Trace Id = X
Span Id = D
Client Sent
That means that the current span has *Trace-Id* set to *X*, *Span-Id* set to *D*. It also has emitted
*Client Sent* event.
This is how the visualization of the parent / child relationship of spans would look like:
image::parents.png[Parent child relationship]
=== Purpose
In the following sections the example from the image above will be taken into consideration.
==== Distributed tracing with Zipkin
Altogether there are *10 spans* . If you go to traces in Zipkin you will see this number:
image::zipkin-traces.png[Traces]
However if you pick a particular trace then you will see *7 spans*:
image::zipkin-ui.png[Traces Info propagation]
NOTE: When picking a particular trace you will see merged spans. That means that if there were 2 spans sent to
Zipkin with Server Received and Server Sent / Client Received and Client Sent
annotations then they will presented as a single span.
In the image depicting the visualization of what *Span* and *Trace* is you can see 20
colorful labels. How does it happen that in Zipkin 10 spans are received?
- 2 span *A* labels signify span started and closed. Upon closing a single span is sent to Zipkin.
- 4 span *B* labels are in fact are single span with 4 annotations. However this span is composed of
two separate instances. One sent from service 1 and one from service 2. So in fact two span instances will be sent
to Zipkin and merged there.
- 2 span *C* labels signify span started and closed. Upon closing a single span is sent to Zipkin.
- 4 span *B* labels are in fact are single span with 4 annotations. However this span is composed of
two separate instances. One sent from service 2 and one from service 3. So in fact two span instances will be sent
to Zipkin and merged there.
- 2 span *E* labels signify span started and closed. Upon closing a single span is sent to Zipkin.
- 4 span *B* labels are in fact are single span with 4 annotations. However this span is composed of
two separate instances. One sent from service 2 and one from service 4. So in fact two span instances will be sent
to Zipkin and merged there.
- 2 span *G* labels signify span started and closed. Upon closing a single span is sent to Zipkin.
So 1 span from *A*, 2 spans from *B*, 1 span from *C*, 2 spans from *D*, 1 span from *E*, 2 spans from *F* and 1 from *G*.
Altogether *10* spans.
==== Log correlation
When grepping the logs of those four applications by trace id equal to e.g. `2485ec27856c56f4` one would get the following:
[source]
service1.log:2016-02-26 11:15:47.561 INFO [service1,2485ec27856c56f4,2485ec27856c56f4,true] 68058 --- [nio-8081-exec-1] i.s.c.sleuth.docs.service1.Application : Hello from service1. Calling service2
service2.log:2016-02-26 11:15:47.710 INFO [service2,2485ec27856c56f4,9aa10ee6fbde75fa,true] 68059 --- [nio-8082-exec-1] i.s.c.sleuth.docs.service2.Application : Hello from service2. Calling service3 and then service4
service3.log:2016-02-26 11:15:47.895 INFO [service3,2485ec27856c56f4,1210be13194bfe5,true] 68060 --- [nio-8083-exec-1] i.s.c.sleuth.docs.service3.Application : Hello from service3
service2.log:2016-02-26 11:15:47.924 INFO [service2,2485ec27856c56f4,9aa10ee6fbde75fa,true] 68059 --- [nio-8082-exec-1] i.s.c.sleuth.docs.service2.Application : Got response from service3 [Hello from service3]
service4.log:2016-02-26 11:15:48.134 INFO [service4,2485ec27856c56f4,1b1845262ffba49d,true] 68061 --- [nio-8084-exec-1] i.s.c.sleuth.docs.service4.Application : Hello from service4
service2.log:2016-02-26 11:15:48.156 INFO [service2,2485ec27856c56f4,9aa10ee6fbde75fa,true] 68059 --- [nio-8082-exec-1] i.s.c.sleuth.docs.service2.Application : Got response from service4 [Hello from service4]
service1.log:2016-02-26 11:15:48.182 INFO [service1,2485ec27856c56f4,2485ec27856c56f4,true] 68058 --- [nio-8081-exec-1] i.s.c.sleuth.docs.service1.Application : Got response from service2 [Hello from service2, response from service3 [Hello from service3] and from service4 [Hello from service4]]
If you're using a log aggregating tool like Kibana, Splunk etc. you can order the events that took place
== Features
@@ -28,21 +115,44 @@ Spans are started and stopped, and they keep track of their timing information.
2016-02-02 15:31:01.936 INFO [bar,46ab0d418373cbc9,46ab0d418373cbc9,false] 23030 --- [nio-8081-exec-4] ...
----
+
(notice the `[appname,traceId,spanId,exportable]` entries from the MDC).
notice the `[appname,traceId,spanId,exportable]` entries from the MDC:
* Optionally log span data in JSON format for harvesting in a log aggregator (set `spring.sleuth.log.json.enabled=true`).
- *spanId* - the id of a specific operation that took place
- *appname* - the name of the application that logged the span
- *traceId* - the id of the latency graph that contains the span
- *exportable* - whether the log should be exported to Zipkin or not
* Provides an abstraction over common distributed tracing data models: traces, spans (forming a DAG), annotations, key-value annotations. Loosely based on HTrace, but Zipkin (Dapper) compatible.
* Provides an abstraction over common distributed tracing data models: traces, spans (forming a DAG), annotations,
key-value annotations. Loosely based on HTrace, but Zipkin (Dapper) compatible.
* Instruments common ingress and egress points from Spring applications (servlet filter, rest template, scheduled actions, message channels, zuul filters, feign client).
* Sleuth records timing information to aid in latency analysis. Using sleuth, you can pinpoint causes of
latency in your applications. Sleuth is written to not log too much, and to not cause your production application to crash.
- propagates structural data about your call-graph in-band, and the rest out-of-band.
- includes opinionated instrumentation of layers such as HTTP
- includes sampling policy to manage volume
- can report to a Zipkin system for query and visualization
* If `spring-cloud-sleuth-zipkin` then the app will generate and collect Zipkin-compatible traces (using Brave). By default it sends them via HTTP to a Zipkin server on localhost (port 9411). Configure the location of the service using `spring.zipkin.[host,port]`.
* Instruments common ingress and egress points from Spring applications (servlet filter, async endpoints,
rest template, scheduled actions, message channels, zuul filters, feign client).
* If `spring-cloud-sleuth-stream` then the app will generate and collect traces via Spring Cloud Stream. Your app automatically becomes a producer of tracer messages that are sent over your broker of choice (e.g. RabbitMQ, Apache Kafka, Redis).
* Provides simple metrics of accepted / dropped spans.
If using Zipkin or Stream, configure the percentage of spans exported using `spring.sleuth.sampler.percentage` (default 0.1, i.e. 10%).
* If `spring-cloud-sleuth-zipkin` then the app will generate and collect Zipkin-compatible traces.
By default it sends them via HTTP to a Zipkin server on localhost (port 9411).
Configure the location of the service using `spring.zipkin.baseUrl`.
NOTE: the SLF4J MDC is always set and logback users will immediately see the trace and span ids in logs per the example above. Other logging systems have to configure their own formatter to get the same result. The default is `logging.pattern.level` set to `%clr(%5p) %clr([${spring.application.name:},%X{X-Trace-Id:-},%X{X-Span-Id:-},%X{X-Span-Export:-}]){yellow}` (this is a Spring Boot feature for logback users).
* If `spring-cloud-sleuth-stream` then the app will generate and collect traces via https://github.com/spring-cloud/spring-cloud-stream[Spring Cloud Stream].
Your app automatically becomes a producer of tracer messages that are sent over your broker of choice
(e.g. RabbitMQ, Apache Kafka, Redis).
IMPORTANT: If using Zipkin or Stream, configure the percentage of spans exported using `spring.sleuth.sampler.percentage`
(default 0.1, i.e. 10%). *Otherwise you might think that Sleuth is not working cause it's omitting some spans.*
NOTE: the SLF4J MDC is always set and logback users will immediately see the trace and span ids in logs per the example
above. Other logging systems have to configure their own formatter to get the same result. The default is
`logging.pattern.level` set to `%clr(%5p) %clr([${spring.application.name:},%X{X-Trace-Id:-},%X{X-Span-Id:-},%X{X-Span-Export:-}]){yellow}`
(this is a Spring Boot feature for logback users).
*This means that if you're not using SLF4J this pattern WILL NOT be automatically applied*.
== Running the samples
@@ -71,7 +181,7 @@ The Ribbon sample makes an interesting demo or playground for learning about zip
NOTE: You can see the zipkin spans without the UI (in logs) if you run the sample with `sample.zipkin.enabled=false`.
image::https://raw.githubusercontent.com/spring-cloud/spring-cloud-sleuth/master/docs/src/main/asciidoc/images/zipkin-trace-screenshot.png[Eample Zipkin Screenshot]
image::https://raw.githubusercontent.com/spring-cloud/spring-cloud-sleuth/master/docs/src/main/asciidoc/images/zipkin-trace-screenshot.png[Sample Zipkin Screenshot]
> The fact that the first trace in says "testSleuthMessaging" seems to be a bug in the UI (it has some annotations from that service, but it originates in the "testSleuthRibbon" service).
@@ -213,6 +323,11 @@ enabled. Intellij 14.1+ requires some configuration to ensure these are setup pr
Maven is well supported by most Java IDEs. Refer to you vendor documentation.
IMPORTANT: There are 2 different versions of language level used in Spring Cloud Sleuth. Java 1.7 is used for main sources and
Java 1.8 is used for tests. When importing your project to an IDE please activate the `ide` Maven profile to turn on
Java 1.8 for both main and test sources. Of course remember that you MUST NOT use Java 1.8 features in the main sources. If you do
so your app will break during the Maven build.
== Contributing
Spring Cloud is released under the non-restrictive Apache 2.0 license,