Custom instrumentation with OpenTelemetry custom-instrumentation

When OpenTelemetry is enabled for your environment, AEM as a Cloud Service traces every request and exports JVM, HTTP, and AEM metrics automatically. That telemetry describes AEM. It shows that a page took 900 milliseconds to render and which components it rendered. It cannot show what your own code was doing, such as which list item a repository query was for and whether it found anything, or which pages fall back to an expensive search because an author left out a field.

You can add that knowledge yourself with the OpenTelemetry API. The spans and attributes that your code creates travel with the automatic telemetry: same service name, same processing, same APM provider. You do not configure an endpoint, a credential, or an exporter in your code.

If you are new to OpenTelemetry on AEM as a Cloud Service, start with the tutorial Observability via OpenTelemetry to learn how it works. Then follow Configure OpenTelemetry for insights into AEM applications to enable it for your environment.

The examples on this page instrument the WKND reference site. Each example describes what you want to achieve, the code to add, and the outcome you can expect in your APM provider. The complete instrumented code, including unit tests that assert on the spans, is on the tutorial/otel-custom-instrumentation branch of the WKND repository.

How custom instrumentation works how-it-works

Set up your project set-up-project

Step 1: Add the OpenTelemetry API add-api

Add the OpenTelemetry API and the instrumentation annotations to the dependencyManagement section of your project’s parent pom.xml, with the provided scope:

<properties>
    <opentelemetry.version>1.61.0</opentelemetry.version>
    <opentelemetry-instrumentation.version>2.27.0</opentelemetry-instrumentation.version>
</properties>

<dependencyManagement>
    <dependencies>
        <dependency>
            <groupId>io.opentelemetry</groupId>
            <artifactId>opentelemetry-api</artifactId>
            <version>${opentelemetry.version}</version>
            <scope>provided</scope>
        </dependency>
        <dependency>
            <groupId>io.opentelemetry.instrumentation</groupId>
            <artifactId>opentelemetry-instrumentation-annotations</artifactId>
            <version>${opentelemetry-instrumentation.version}</version>
            <scope>provided</scope>
        </dependency>
    </dependencies>
</dependencyManagement>

Then add both dependencies, without versions, to the pom.xml of each bundle that uses them, such as core/pom.xml:

<dependency>
    <groupId>io.opentelemetry</groupId>
    <artifactId>opentelemetry-api</artifactId>
</dependency>
<dependency>
    <groupId>io.opentelemetry.instrumentation</groupId>
    <artifactId>opentelemetry-instrumentation-annotations</artifactId>
</dependency>

Use opentelemetry-api 1.61.0 and opentelemetry-instrumentation-annotations 2.27.0, or earlier versions. They match the OpenTelemetry Java agent that AEM as a Cloud Service runs, and later versions of the agent continue to support them. API features added after the version that the agent supports have no effect.

Step 2: Embed the API in your bundle embed-api

AEM as a Cloud Service does not export the OpenTelemetry API packages, so each bundle that uses the API must contain its own copy. Add the following instructions to the bnd configuration of your bundle. With the AEM Project Archetype, that is the bnd-maven-plugin configuration in core/pom.xml. Keep any entries that your Import-Package instruction already has.

Import-Package: !io.opentelemetry.*,javax.annotation;version=0.0.0,*
-includepackage: io.opentelemetry.*

Each bundle that uses the API embeds its own copy, and the agent connects each copy separately.

Step 3: Create a tracer create-tracer

Create one Tracer for your code base and reuse it everywhere. In WKND, a small class holds it:

package com.adobe.aem.guides.wknd.core.telemetry;

import io.opentelemetry.api.GlobalOpenTelemetry;
import io.opentelemetry.api.trace.Tracer;

public final class WkndTelemetry {

    /** Instrumentation scope: identifies telemetry produced by WKND code in your APM provider. */
    public static final String SCOPE = "com.adobe.aem.guides.wknd";

    public static final Tracer TRACER = GlobalOpenTelemetry.getTracer(SCOPE);

    private WkndTelemetry() {
    }
}

The scope name appears on every span that you create through this tracer, as the instrumentation scope (or library name). Use a name that identifies your code, such as your project’s base Java package.

Where your spans appear where-spans-appear

On AEM as a Cloud Service, a page request already produces spans from AEM itself. The spans that your code creates are added inside them. For example, this is the path to the Image List component in a trace of the WKND Magazine page:

GET /*                                                     the request (AEM)
└─ SlingMainServlet.service                                Sling request processing (AEM)
   └─ AEM component: cq:Page                               (AEM)
      └─ AEM component: wknd/components/page               the page component (AEM)
         └─ HTL: libs.core.wcm.components.page.v3.page.page__002e__html
            └─ ...                                         containers and layout grids (AEM)
               └─ AEM component: wknd/components/image-list
                  └─ HTL: apps.wknd.components.image__002d__list.image__002d__list__002e__html
                     └─ ...                                spans that the Image List's Sling Model creates

While a component renders, the span of its HTL script is the current span. A Sling Model that the script loads with data-sly-use runs inside that span, so spans that the model creates become its children.

Every request span is named GET /* (or POST /*, and so on). To find the traces for a particular page, search on the url.path attribute of the request span, or add your own attributes, as shown in Example 3.

Examples examples

Example 1: Trace an expensive operation trace-operation

What you want to achieve trace-operation-goal

The WKND Image List component (wknd/components/image-list) displays a list of pages, each with its first image. To find that image, its Sling Model, ImageListImpl, runs one QueryBuilder query for every item in the list. AEM’s own spans already show those queries: on the WKND Magazine page, which lists five articles, the trace contains five JCR query spans under the Image List’s HTL span. They do not show which list item each query was for, whether it found an image, or the time spent processing the results. The original code timed the query with System.currentTimeMillis() and wrote the result to a DEBUG log entry, which is not available in production. You want each query to appear in the trace as a named operation, with that context.

The code trace-operation-code

In ImageListImpl.findPageComponentResources(), create a span around the query:

import io.opentelemetry.api.trace.Span;
import io.opentelemetry.api.trace.StatusCode;
import io.opentelemetry.context.Scope;

// ... build the QueryBuilder parameters, as before

final Span span = WkndTelemetry.TRACER.spanBuilder("ImageList.findPageComponentResources")
        .setAttribute("wknd.query.path", page.getContentResource().getPath())
        .setAttribute("wknd.query.resource_type", slingResourceType)
        .setAttribute("wknd.query.limit", limit)
        .startSpan();

try (Scope ignored = span.makeCurrent()) {
    // ... run the query and collect the resources, as before

    span.setAttribute("wknd.query.result_count", componentResources.size());
} catch (RuntimeException e) {
    span.recordException(e);
    span.setStatus(StatusCode.ERROR, "Image List query failed");
    throw e;
} finally {
    span.end();
}

return componentResources;

The outcome trace-operation-outcome

On the WKND Magazine page, which lists five articles, the trace now contains five ImageList.findPageComponentResources spans inside the Image List, one for each list item. Each one is the parent of the JCR query span that AEM creates for its query:

AEM component: wknd/components/image-list
└─ HTL: apps.wknd.components.image__002d__list.image__002d__list__002e__html
   ├─ ImageList.findPageComponentResources        your span
   │  └─ JCR query                                AEM
   ├─ ImageList.findPageComponentResources
   │  └─ JCR query
   └─ ...                                         three more

Each of your spans has the instrumentation scope com.adobe.aem.guides.wknd and the following attributes:

You can now see, for each list item, which page the query searched, whether it found an image (wknd.query.result_count is 0 when it did not), and how long the whole lookup took, including processing the results. On the WKND Magazine page, each lookup takes about 6.5 milliseconds, of which the repository query itself takes about 3.5: half of the time goes into processing the results, which AEM’s own spans do not show. Because the query count grows with the length of the list, you can also see how much of the component’s rendering time the lookups account for.

Example 2: Trace a method with an annotation with-span

What you want to achieve with-span-goal

WKND’s SocialImageImpl model runs on every page to fill in the og:image meta tag. If an author has not set a featured image, the model walks the page’s content tree to find the first image, visiting up to 500 resources. You want to know how often that walk runs, and how much of the tree it visits, without restructuring the method.

The code with-span-code

Annotate the method with @WithSpan:

import io.opentelemetry.api.trace.Span;
import io.opentelemetry.instrumentation.annotations.WithSpan;

@WithSpan("SocialImage.resolveFromFirstImageOnPage")
protected boolean resolveFromFirstImageOnPage() {
    Resource contentResource = currentPage.getContentResource();
    if (contentResource == null) {
        return false;
    }

    int[] visitedCount = new int[]{0};
    Resource firstImage = findFirstImage(contentResource, 0, visitedCount);

    // Span.current() is the span that @WithSpan started for this method.
    Span.current().setAttribute("wknd.social_image.nodes_visited", visitedCount[0]);
    Span.current().setAttribute("wknd.social_image.walk_truncated", visitedCount[0] > MAX_NODES_TO_VISIT);

    // ... use firstImage, as before
}

The outcome with-span-outcome

A SocialImage.resolveFromFirstImageOnPage span appears only in the traces of pages that have no featured image:

Search for this span name to list the pages that need a featured image. If wknd.social_image.walk_truncated is true, the walk stopped at 500 resources and the page may have no social image at all.

Spans created by @WithSpan carry the agent’s instrumentation scope (io.opentelemetry.opentelemetry-instrumentation-annotations-1.16), not yours.

Example 3: Add business context to the current span current-span

What you want to achieve current-span-goal

You want to filter traces by a fact that your code knows, here, where the page’s social image came from, without creating another span.

The code current-span-code

In SocialImageImpl, add an attribute to the span that is already active:

import io.opentelemetry.api.common.AttributeKey;
import io.opentelemetry.api.trace.Span;

private static final AttributeKey<String> IMAGE_SOURCE = AttributeKey.stringKey("wknd.social_image.source");

@PostConstruct
protected void init() {
    if (currentPage == null) {
        return;
    }

    final String source;
    if (resolveFromFeaturedImage()) {
        source = "featured_image";
    } else if (resolveFromFirstImageOnPage()) {
        source = "first_image_on_page";
    } else {
        source = "none";
    }

    Span.current().setAttribute(IMAGE_SOURCE, source);
}

The outcome current-span-outcome

The span of the page’s customheaderlibs.html script, where WKND loads this model, carries wknd.social_image.source with the value featured_image, first_image_on_page, or none. Search for traces where wknd.social_image.source is none to find the pages that are published without a social image.

On the WKND site, every page reports first_image_on_page or none: no page sets a featured image, so every page pays for the content-tree walk from Example 2. Setting a featured image on the most visited pages removes that work.

Example 4: Record an error record-errors

What you want to achieve record-errors-goal

WKND’s ContentAIAvailabilityImpl model checks whether Content AI search is configured by reading an OSGi configuration. If the lookup fails, the model treats Content AI as not configured and logs a warning. The page still renders and the request succeeds, so the failure is easy to miss. You want the failure to appear in your APM provider’s error views, attached to the operation that failed.

The code record-errors-code

import io.opentelemetry.api.trace.Span;
import io.opentelemetry.api.trace.StatusCode;
import io.opentelemetry.context.Scope;

private boolean resolveConfigured() {
    if (configurationAdmin == null) {
        return false;
    }
    final Span span = WkndTelemetry.TRACER.spanBuilder("ContentAIAvailability.resolveConfigured").startSpan();
    // Close the scope in finally, not with try-with-resources: try-with-resources closes it before
    // the catch block runs, and the warning logged there must carry this span's trace and span IDs.
    final Scope scope = span.makeCurrent();
    try {
        Configuration configuration = lookupConfiguration();
        // ... read the API key, as before
        span.setAttribute("wknd.content_ai.configured", isConfigured);
        return isConfigured;
    } catch (IOException e) {
        span.recordException(e);
        span.setStatus(StatusCode.ERROR, "Content AI configuration lookup failed");
        LOGGER.warn("Unable to determine whether Content AI is configured (PID {})", CONTENT_AI_CLIENT_PID, e);
        return false;
    } finally {
        scope.close();
        span.end();
    }
}

The outcome record-errors-outcome

The trace contains a ContentAIAvailability.resolveConfigured span with the status Error and the description Content AI configuration lookup failed. The span has an exception event:

The span counts as an error in your APM provider, so it appears wherever your provider shows failed operations. The request span keeps its status, because the request returned HTTP 200.

Example 5: Correlate logs with traces correlate-logs

What you want to achieve correlate-logs-goal

When the Content AI lookup in Example 4 fails, you want to go from the warning in your logs to the trace of the request that produced it, and back.

The code correlate-logs-code

You do not need any OpenTelemetry code. Log with SLF4J as usual, and enable logs (logs: true) in your OpenTelemetry configuration:

LOGGER.warn("Unable to determine whether Content AI is configured (PID {})", CONTENT_AI_CLIENT_PID, e);

The agent adds the trace and span IDs of the current span to every log entry. Because ContentAIAvailabilityImpl logs while its span from Example 4 is current, the warning is linked to that span.

The outcome correlate-logs-outcome

Your APM provider receives a log entry such as the following, and can show it with its trace:

Best practices best-practices

Test your instrumentation test

Troubleshooting troubleshooting

Related articles related-articles