What is it?

An external, end-to-end view about the performance of ozone views. As an example:

...

With tracing you can identify the slow components during an end-to-end test and go forward with Java Profiler on the identified component.

In this picture we can see that the OM/SCM calls are pretty fast but we have some problem on the freon side before the first writeChunk call.

Getting started

(1) start the cluster from compose/ozonetrace (docker-compose up -d)

cd compose/ozonetrace
docker-compose up -d
docker-compose scale datanode=3

...

(3) Check the output of the tracing. Open http://localhost:16686/search in your broser

How to use it in my own cluster.

(4) Select freon service and click to the Find Tracing.

...

(5) Click to any of the results on the right hand side and open the details view:

The first line represents the full time. Under the first line you can see the time of specific subsystems. The first (bigger) name in the line is the name of the component/JVM (eg. SCM, OM, Freon...) The second one is the name of the trace (usually a method name)

...

From high level, the tracing is very simple. We need to initialize a tracing context which contains a unique identifier. This identifier is stored in a global ThreadLocal variable. The identifier should be propagated over the wire or in case of thread separations. This is not solved by the library we need to do this by own.

The tracing library can report the identifer from various points in the code and can create sub-identifier to show hierarchical results. The jaeger server will correlate the data and display it in a hierarchical way.

What should I do in the code?

We use OpenTracing which is a lightweight interface to do the tracing in a vendor independent way (Similar as slf4j is a common interface for logging frameworks like log4j or logback). Jaeger related API is only used to initialize the tracer, we use pure OpenTracing everywhere else.

...

In each component we need to initialize the tracing. This is already done in most of the components. For example:

public static void main(String[] argv) throws IOException {
  if (DFSUtil.parseHelpArgument(argv, USAGE, System.out, true)) {
    System.exit(0);
  }
  try {
    TracingUtil.initTracing("StorageContainerManager");
    OzoneConfiguration conf = new OzoneConfiguration();
    ...

The TracingUtil.initTracing does all the work, the only thing what we need is a name for the current component/JVM instance.

Instrumentation: Dynamic method

The This is the simplest and best way to add additional tracing information. Let's say you have a Java instance which implements ClientProtocol. To start a new tracing span (record specific timing information) for all the methods, you can create a dynamic proxy:

ClientProtocol protocol = TracingUtil.createProxy(originalClientProtocolInstance, ClientProtocol.class);

We do it for all the RPC clients as we would like to persist the overall time in a each specific components:

ScmBlockLocationProtocolClientSideTranslatorPB scmBlockLocationClient =
    new ScmBlockLocationProtocolClientSideTranslatorPB(
        RPC.getProxy(ScmBlockLocationProtocolPB.class, scmVersion,
            scmBlockAddress, UserGroupInformation.getCurrentUser(), conf,
            NetUtils.getDefaultSocketFactory(conf),
            Client.getRpcTimeout(conf)));

return TracingUtil
    .createProxy(scmBlockLocationClient, ScmBlockLocationProtocol.class);

The first expression is just an RPC client creation. At the end we wrap the original client with a proxy which calls the tracing api around all the methods.

Manual method

Dynamic method is always better, as we can introduce sophisticated configuration to turn on/off the tracing inside the TracingUtil.createProxy call. But you can open a sub measurement (tracing span) at any time with using pure OpenTracing API:

try (Scope writeScope = GlobalTracer.get()
    .buildSpan("writeKeyData")
    .startActive(true)) {
//the do work here which is measured under a separated span
  os.write(keyValue);
  os.write(randomValue);
  os.close();
}

...

See the OpenTracing docs for more details.

Propagation

The most important part to get end-to-end information is propagating the trace id between the components. Hadoop RPC supports only the propagation of HTrace information (which is an other tracing library, but it's retired.) Supporting other tracing libraries are under discussion:

Until we will have a final Hadoop-wide solution we propagate the tracing id in our protobuf messages. For example this is the beginning of the OzoneManagerProtocol.proto

message OMRequest {
  required Type cmdType = 1; // Type of the command

  // A string that identifies this command, we generate  Trace ID in Ozone
  // frontend and this allows us to trace that command all over ozone.
  optional string traceID = 2;

  required string clientId = 3;

  

You can see the traceID there.

Our only task is to serialize the tracing ID during the client call and de-serialize it on the server side. Fortunately we have a pattern to use ....ProtocolClientSideTranslator and ...ProtocolServerSideTranslator classes to encapsulate the RPC logic. We just modified all (=most of) the Client/ServerSideTranslators to propagate our tracing information.

For example this is the serialization from a ClientSideTranslator. It uses the TracingUtil class and it create a String from the current tracing information.

OMRequest payload = OMRequest.newBuilder(omRequest)
    .setTraceID(TracingUtil.exportCurrentSpan())
    .build();

To deserialize it on the server side:

Scope scope = TracingUtil
    .importAndCreateScope(request.getCmdType().name(), request.getTraceID());
try {
  //do the work here
} finally {
  scope.close();
}

This is similar to the Manual method described earlier but it imports the span from the client component and creates a child span for this component in one step.