GitHub user ramanathan1504 created a discussion: [Research] Performance Overhead of Tracing Data in Async Loggers: Map-Injection vs Native Fields
Following discussions on Slack regarding [Issue #1976](https://github.com/apache/logging-log4j2/issues/1976) and [PR #4171](https://github.com/apache/logging-log4j2/pull/4171), [PR #4175](https://github.com/apache/logging-log4j2/pull/4175) with @ppkarwasz and @vy, I wanted to open this thread to gather research on how different observability frameworks currently pass distributed tracing data (`traceId`, `spanId`, `traceFlags`) to Log4j across asynchronous boundaries. The core question we need to figure out: **Do existing Map-based APIs (like `ContextDataProvider` or SLF4J MDC) handle async thread handoffs efficiently enough, or does Log4j need a new native fast-path (like a `TraceContextProvider` SPI with native `LogEvent` fields) to achieve zero-allocation tracing?** ### The "Baggage" Reality Before diving into the data, it's important to call out one key reality upfront: frameworks like OpenTelemetry don't just inject Trace IDs—they also inject "Baggage" (dynamic user-defined tags). Because native fields can't handle dynamic baggage, **any complete solution must gracefully handle both a fast-path for the standard W3C IDs, and a map-fallback for Baggage.** Here is the verified state of the ecosystem today: --- ### 1. Micrometer Tracing / Spring Boot (The SLF4J MDC Path) Frameworks like Micrometer (the default in Spring Boot 3) rely heavily on the SLF4J `MDCAdapter`, which pushes trace IDs directly into Log4j's `ThreadContext` map. * **The Bottleneck:** When using Asynchronous Loggers (LMAX Disruptor), Log4j is forced to perform a deep, copy-on-write clone of the entire `ThreadContext` map to safely hand the data over to the background thread. Under high throughput, this generates massive JVM heap garbage and triggers frequent GC pauses. * **Maintainer Feedback:** I discussed this with `Jonatan Ivanov` (Micrometer/Spring Boot maintainer). He was very supportive of a native SPI to bypass the MDC, noting that Spring Boot already implements a similar native interface (`SpanContextSupplier`) specifically to fetch Trace/Span IDs natively for Prometheus exemplars without map allocations. ### 2. OpenTelemetry & APMs (The `ContextDataProvider` Path) To avoid the `ThreadContext` deep-copy issue, modern APM agents (like OpenTelemetry and Elastic APM) bypass the MDC by implementing Log4j's `ContextDataProvider` SPI. * **The Code:** Looking at OTel's [`OpenTelemetryContextDataProvider.java`](https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/main/instrumentation/log4j/log4j-context-data/log4j-context-data-2.17/library-autoconfigure/src/main/java/io/opentelemetry/instrumentation/log4j/contextdata/v2_17/OpenTelemetryContextDataProvider.java), the agent is forced to allocate a `new StringMap()` (and its backing arrays) for *every single log event* to supply the data. * **The Bottleneck:** While this avoids the MDC, it introduces a new penalty. Log4j's `ContextDataInjector` must safely merge this data. In an Async environment, if the RingBuffer slot's map is frozen, Log4j must allocate a *new* map to safely complete the merge, resulting in heap allocations and `O(log N)` binary search overhead on the hot path. * **Maintainer Feedback:** I discussed this with the OpenTelemetry team (`Lauri Tulmin`). He confirmed that while native fields are great for the core IDs, OTel still needs the map injection anyway to support dynamic Baggage. --- ### 3. The Benchmark Data (Map-merging vs. Native Fields) To quantify the overhead of these current approaches, I ran a JMH GC Allocation profile (`-prof gc`) simulating the Async RingBuffer handoff. | Benchmark Scenario | Mode | Score (Throughput) | Alloc Rate | | :--- | :--- | :--- | :--- | | **`baseline`** (No tracing) | thrpt | `1.210 ops/us` | `1280 B/op` | | **`nativeTracing`** (Native Fields SPI) | thrpt | `1.193 ops/us` | `1280 B/op` **(+0 Bytes)** | | **`threadContextTracing`** (SLF4J / MDC) | thrpt | `1.071 ops/us` | `1552 B/op` *(+272 Bytes)* | | **`contextDataProviderTracing`** (OTel Map) | thrpt | `0.668 ops/us` | `2752 B/op` *(+1472 Bytes)* | *Note: The `contextDataProvider` simulation accounts for both the OTel Map instantiation and the Log4j internal `ContextDataInjector` merge/unfreeze allocations.* --- ### Where Does This Leave Us? The data and maintainer feedback reveal a difficult reality: As long as core tracing metadata is injected into a **Map-based structure**, we incur heavy allocation and merging overhead during asynchronous logging boundaries (cutting throughput by ~45% and generating +1,472 bytes of garbage per event). However, as Volkan and the OTel team pointed out, adding native fields to `LogEvent` doesn't magically solve everything if agents still have to inject dynamic Baggage via maps anyway. So, what is the best path forward for Log4j? 1. **Can we optimize Map Merging?** Is there a way to optimize `ContextDataProvider` and `ContextDataInjector` to be 100% garbage-free when merging maps into frozen async events? 2. **Is a Hybrid Approach Justified?** Given that W3C tracing is now a universal application standard, does it warrant its own native fields on `LogEvent` to guarantee a zero-allocation fast-path for the IDs, even if dynamic Baggage remains relegated to the map? Looking forward to the community's thoughts! GitHub link: https://github.com/apache/logging-log4j2/discussions/4179 ---- This is an automatically sent email for [email protected]. To unsubscribe, please send an email to: [email protected]
