In our projects, we utilize a microservices architecture. When performance bottlenecks arise, a significant amount of time is spent monitoring and analyzing logs. When logging the timings of individual operations to a log file, it is typically challenging to understand what triggered those operations, track the sequence of actions, or determine the time offsets of one operation relative to another across different services.
To minimize manual labor, we decided to use one of the tracing tools. This article will discuss how and why tracing can be used, as well as our experiences with it.
What problems can be solved with tracing
- Identifying performance bottlenecks both within a single service and across the entire execution tree among all involved services. For example:
- A series of many short consecutive calls between services, for instance, for geocoding or querying the database.
- Long waits for input/output, such as data transfer over the network or reading from disk.
- Long data parsing operations.
- Long operations that require CPU.
- Code segments that are unnecessary for obtaining the final result and can be removed or executed lazily.
- Visually understand the order in which calls occur and what happens when an operation is executed.
It is clear that, for example, a request arrived at service WS -> service WS supplemented data via service R -> then sent a request to service V -> service V loaded a lot of data from service R -> went to service P -> service P went back to service R -> service V ignored the result and went to service J -> and only then returned the response to service WS, while continuing to compute something else in the background.
Without such a trace or detailed documentation for the entire process, it is very difficult to understand what is happening when looking at the code for the first time, especially since the code is scattered across various services and hidden behind a multitude of beans and interfaces. - Gathering information about the execution tree for subsequent deferred analysis. At each step of execution, additional information can be added to the trace that is available at that stage, allowing further investigation into what input data led to the particular scenario. For example:
- User ID
- Permissions
- Selected method type
- Log or execution error
- Transforming traces into a subset of metrics and further analysis in the form of metrics.
What tracing can log. Span
In tracing, there is the concept of a span, which is analogous to a single log in the console. A span has:
- A name, usually this is the name of the method that was executed
- The name of the service in which the span was generated
- A unique ID
- Some meta-information in the form of key/value that has been logged into it. For example, method parameters or whether the method finished with an error or not
- Start and end time of the execution of this span
- Parent span ID
Each span is sent to the span collector for storage in the database for later viewing as soon as it completes its execution. Subsequently, a tree of all spans can be constructed by connecting them by parent ID. During analysis, it is possible to find, for example, all spans in a service that took longer than a specified time. Then, by clicking on a specific span, you can see the entire tree above and below this span.
Opentrace, Jaeger, and how we implemented this for our projects
There is a general standard , which describes how and what should be collected, without tying tracing to a specific implementation in any language. For example, in Java, all work with traces is done through the common Opentrace API, while underneath it there may be Jaeger or a blank default implementation that does nothing.
We use as the implementation of Opentrace. It consists of several components:
- Jaeger-agent — a local agent that is usually on each machine and to which services log to a local default port. If there is no agent, then traces of all services on that machine are usually turned off
- Jaeger-collector — all agents send the collected traces to it, and it saves them in the chosen database
- Database — their preferred is Cassandra, but we use Elasticsearch, there are implementations for a couple of other databases, and an in-memory implementation that does not save anything to disk
- Jaeger-query — this service queries the database and returns the collected traces for analysis
- Jaeger-ui — this is the web interface for searching and viewing traces, it queries Jaeger-query
A separate component can be called the Opentrace Jaeger implementation for specific languages, through which spans are sent to Jaeger-agent.
The process involves implementing the interface io.opentracing.Tracer, after which all traces will be sent to the actual agent through it.
You can also connect to Spring components and the implementation from Jaeger which will automatically configure tracing for everything that passes through these components, such as HTTP requests to controllers, database queries through JDBC, etc.
Logging traces in Java
At the very top level, the first Span should be created, which can be done automatically by a Spring controller when receiving a request, or manually if there isn't one. It is then passed through to lower Scope levels. If any method further down wants to add a Span, it takes the current activeSpan from Scope, creates a new Span, indicates that its parent is the obtained activeSpan, and makes the new Span active. When calling external services, the current active span is passed to them, and those services create new spans tied to this span.
All operations are done through an instance of Tracer, which can be obtained via the DI mechanism or GlobalTracer.get() as a global variable if the DI mechanism does not work. By default, if the tracer has not been initialized, a NoopTracer will be returned, which does nothing.
Next, the current scope is retrieved from the tracer through ScopeManager, a new scope is created from the current one with the new span attached, and subsequently, the created Scope is closed, which closes the created span and returns the previous Scope to an active state. The Scope is tied to the thread, so in multithreaded programming, it is essential to remember to pass the active span to another thread for the activation of that thread's Scope linked to this span.
io.opentracing.Tracer tracer = ...; // GlobalTracer.get()
void DoSmth () {
try (Scope scope = tracer.buildSpan("DoSmth").startActive(true)) {
...
}
}
void DoOther () {
Span span = tracer.buildSpan("someWork").start();
try (Scope scope = tracer.scopeManager().activate(span, false)) {
// Do things.
} catch(Exception ex) {
Tags.ERROR.set(span, true);
span.log(Map.of(Fields.EVENT, "error", Fields.ERROR_OBJECT, ex, Fields.MESSAGE, ex.getMessage()));
} finally {
span.finish();
}
}
void DoAsync () {
try (Scope scope = tracer.buildSpan("ServiceHandlerSpan").startActive(false)) {
...
final Span span = scope.span();
doAsyncWork(() -> {
// STEP 2 ABOVE: reactivate the Span in the callback, passing true to
// startActive() if/when the Span must be finished.
try (Scope scope = tracer.scopeManager().activate(span, false)) {
...
}
});
}
}For multithreaded programming, there is also TracedExecutorService and similar wrappers that automatically propagate the current span into the thread when starting asynchronous tasks:
private ExecutorService executor = new TracedExecutorService(
Executors.newFixedThreadPool(10), GlobalTracer.get()
);For external HTTP requests, there is
HttpClient httpClient = new TracingHttpClientBuilder().build();The issues we encountered
- Beans and DI do not always work if the tracer is not used in a service or component, then Tracer may not work and you will have to use GlobalTracer.get().
- Annotations do not work if it is not a component or service, or if the method call occurs from another method of the same class. You must be careful, check what works, and use manual trace creation if @Traced does not work. You can also attach an additional compiler for Java annotations, then they should work everywhere.
- In older Spring and Spring Boot, the auto-configuration of opentracing Spring Cloud does not work due to bugs in DI, so if you want traces to work automatically in Spring components, you can do it similarly to
- In Groovy, try-with-resources does not work, you must use try finally.
- Each service must specify its own spring.application.name under which the traces will be logged. Moreover, a separate name for production and testing is needed to avoid interference.
- If you use GlobalTracer and Tomcat, all services launched in this Tomcat have one GlobalTracer, so they will all have the same service name.
- When adding traces to a method, you must ensure that it is not called in a loop many times. You should add one common trace for all calls that logs the total execution time. Otherwise, excessive load will be created.
- Once in jaeger-ui, we made too large requests for a large number of traces and since we didn't wait for a response, we made it again. As a result, jaeger-query started consuming a lot of memory and slowing down Elastic. A restart of jaeger-query helped.
Sampling, storage, and viewing of traces
There are three types :
- Const which sends and saves all traces.
- Probabilistic which filters traces with a certain given probability.
- Rate limiting that restricts the number of traces per second. These parameters can be configured on the client, either on jaeger-agent or in the collector. Currently, we use const 1 in our stack of validators since there are not too many requests, but they take a considerable amount of time. In the future, if this causes excessive load on the system, we can limit it.
If using Cassandra, by default it retains traces for only two days. We use and traces are stored indefinitely and are not deleted. A separate index is created for each day, for example, jaeger-service-2019-03-04. In the future, automatic cleanup of old traces needs to be configured.
To view traces, you need to:
- Select the service you wish to filter traces by, for example, tomcat7-default for a service that is running in Tomcat and cannot have its own name.
- Then select the operation, time frame, and minimum operation duration, for instance, from 10 seconds, to capture only the long-running executions.
- Go into one of the traces and see what caused the slowdown.
Additionally, if a request ID is known, it can be found by searching with tags if this ID is logged in the trace span.
Documentation
- OpenTracing documentation
- Jaeger documentation
- Jaeger Java integration
- Spring OpenTracing integration
Articles
- Jaeger OpenTracing and Microservices in a real project using PHP and Golang
- Evolving Distributed Tracing at Uber Engineering
- Running Jaeger Agent on bare metal
Video
- How We Used Jaeger and Prometheus to Deliver Lightning-Fast User Queries — Bryan Boreham
- Intro: Jaeger — Yuri Shkuro, Uber & Pavol Loffay, Red Hat
- Serghei Iakovlev, “A Little Story of a Great Victory: OpenTracing, AWS, and Jaeger”
Source: habr.com
