A typical microservices architecture consists of several microservices. These services send output to a log file; traditionally, each service sends output to its own log file. When looking at log files across server instances, it is almost never trivial to follow a single trace of execution across our microservices; for example, let’s say we have two services, A and B, and that service A serves as a client for service B. Typically, we will see several calls to service B from service A in the logs, but it is seldom trivial to match which calls from service A match which calls received from service B. Additionally, it is possible service B may be called from clients other than service A, making following a single trace of execution in our application a challenging task. This is where the MicroProfile OpenTracing API comes in; this API generates spans and traces that allow us to trace execution across Payara Micro instances; each span and trace has a unique ID that does not change across instances, allowing us to link log entries from one instance of Payara Micro to another.
Before we can use the MicroProfile OpenTracing API, it needs to be enabled in Payara Micro.
Enabling Request Tracing in Payara Micro
By default, any request taking longer than 30 seconds will be traced. Output is sent to the Payara Micro console in JSON format.
NANOSECONDS
MICROSECONDS
MILLISECONDS
SECONDS
MINUTES
HOURS
DAYS
All values for --requestTracingThresholdUnit are case insensitive.
The preceding command is an alternative way to configure request tracing so that any request taking longer than 100 milliseconds is traced. The optional value of --enableRequestTracing must be an integer value followed by a unit of time, without any spaces between them.
Valid values for units of time could be the spelled-out unit of time (i.e., “nanoseconds”), or the equivalent abbreviation (i.e., “ns”).
Request Tracing Units of Time
Unit of Time | Spelled-Out Value (Case Insensitive) | Abbreviated Value |
|---|---|---|
Nanoseconds | nanoseconds | ns |
Microseconds | microseconds | us or μs |
Milliseconds | milliseconds | ms |
Seconds | seconds | s |
Minutes | minutes | m |
Hours | hours | h |
Days | days | d |
All spelled-out values also accept their singular counterparts (nanosecond, microsecond, etc.).
Spans and Traces
A span represents an individual unit of work, typically a single HTTP request; by default, Payara Micro logs spans in JSON format to its console output.
A trace is a collection of related spans; for example, we could send an HTTP request to a microservice, which in turn sends two more requests to two additional microservices; all three requests in this case would have unique span IDs, but all would share the same trace ID; by looking at the trace ID of each span, we can find out which requests are related. Trace IDs are unique and match even across Payara Micro instances, making it possible to relate log entries in one Payara Micro instance to another.
To slow down processing a bit and make sure our hireEmployee() method gets traces, we added a 100-ms delay to the method.
If we enable request tracing with a threshold of 100 ms and send an HTTP POST request to http://localhost:8081/requesttracingclient/webresources/employeeclient/hire, we can see all generated spans on the Payara Micro output for both instances of Payara Micro: the one running the employee client service and the one running the employee service.
This is JSON-formatted trace with six spans; each span has useful data such as the operation name, span ID, trace ID, start and end times, and trace duration.
The first two spans in the output, with operation names of “processContainerRequest” and “processWebserviceRequest”, are internal Payara Micro calls that get added to the trace.
Notice that in the output, each individual span has a unique ID; however, the trace ID is identical in each one of them; this trace ID is what we can use to link individual requests to a single trace of execution.
In this case, we see only a single HTTP PUT request being traced; the reason we don’t see all three HTTP PUT requests is because we specified a threshold of 100 ms for request tracing when we started this instance of Payara Micro; the other two PUT requests took less than 100 ms; therefore, they were not traced. Note that the trace ID matches the value of the corresponding trace ID on the instance running the client service, allowing us to correlate the invocations.
Customizing Request Tracing
As seen in the previous section, by simply enabling request tracing and specifying a threshold, we get a lot of functionality, which will suffice for most cases. However, we can customize request tracing if the default functionality does not fit our needs.
The MicroProfile OpenTracing API includes a @Traced annotation that allows us to trace methods other than webservice endpoints; it also allows us to disable tracing for any method and to customize the operation name.
We can also further customize request tracing output via the Tracer annotation, which can be used to add additional information to spans, as well as to create additional spans not bound to a method.
Tracing Additional Methods
We can trace any method on a CDI bean by decorating it with the @Traced annotation.
Annotating a CDI bean with @Traced at the class level will result in all methods in the bean being traced.
Disabling Request Tracing
Customizing the Operation Name
By default, the generated operation name in a span is the fully qualified name of the method being invoked (if the method was invoked as the direct result of an HTTP request, then the method name is preceded by the HTTP request type (PUT, GET, POST, etc.).
Adding Additional Information to Spans
Most Maven projects for applications to be deployed to Payara Micro should include the payara-bom dependency in its <dependencyManagement> section.
A Maven Bill of Materials (BOM) dictates the correct version of dependencies to our project. By using a BOM, we can add a dependency to our project without specifying its version, the correct version that will work with our other dependencies is declared in the BOM.
payara-bom includes a dependency for opentracing-api in its <dependencyManagement> section; therefore, when adding this dependency to our project, we don’t need to specify a version, as seen in the preceding pom.xml file.
As we can see in the example, we obtain an instance of io.opentracing.Span representing the current span by invoking Tracer.activeSpan(); from that, we invoke the setTag() method, which has two parameters: a String for the tag name, plus an additional parameter for the value. There are three overloaded versions of setTag(); the second parameter could be a String, a boolean, or a Number (any numeric value); in our example, we used the version with two Strings, since we are adding a tag containing the hired employee’s first and last names.
Creating Additional Spans
Tracer.buildSpan() creates an instance of the SpanBuilder class, which is an inner class of Tracer; this method takes a single argument, a String indicating the operation name of our custom span.
to add a tag labeled foo with a value of bar to our custom span.
Summary
In this chapter, we covered the request tracing capabilities of Payara Micro. We saw how to enable request tracing via a command-line argument to Payara Micro, which results in all of the RESTful web service endpoints in our application being automatically traced. We also covered how to trace additional methods in our applications via the @Traced annotation, as well as how to disable request tracing in places where it is not desired. Additionally, we covered how to customize the operation name in the spans generated by our applications, as well as how to add custom tags to our spans. Finally, we covered how to programmatically create spans in case we need more control than what is provided by the MicroProfile OpenTracing API.