From cfc2f495ce9e83c9a19d0d703fc55316d1e0838c Mon Sep 17 00:00:00 2001 From: Sjoerd Talsma Date: Fri, 8 Nov 2024 20:42:24 +0100 Subject: [PATCH] Extend ContextTimer api with thrown errors. Signed-off-by: Sjoerd Talsma --- .../talsmasoftware/context/api/Context.java | 2 +- .../context/api/ContextManager.java | 1 + .../context/api/ContextSnapshot.java | 2 +- .../context/api/ContextTimer.java | 21 +-- .../context/core/ContextManagers.java | 150 ++++++++++-------- .../talsmasoftware/context/core/Timers.java | 4 +- .../context/core/TimersTest.java | 4 +- .../timers/metrics/MetricsContextTimer.java | 50 +++--- .../metrics/MetricsContextTimerTest.java | 15 +- .../micrometer/MicrometerContextTimer.java | 3 +- .../MicrometerContextTimerTest.java | 2 +- .../opentracing/OpentracingContextTimer.java | 23 ++- 12 files changed, 165 insertions(+), 112 deletions(-) diff --git a/context-propagation-api/src/main/java/nl/talsmasoftware/context/api/Context.java b/context-propagation-api/src/main/java/nl/talsmasoftware/context/api/Context.java index 3c201145..7b333a5b 100644 --- a/context-propagation-api/src/main/java/nl/talsmasoftware/context/api/Context.java +++ b/context-propagation-api/src/main/java/nl/talsmasoftware/context/api/Context.java @@ -42,7 +42,7 @@ * * @param Type of the context value. * @author Sjoerd Talsma - * @since 1.1.0 + * @since 2.0.0 */ public interface Context extends Closeable { diff --git a/context-propagation-api/src/main/java/nl/talsmasoftware/context/api/ContextManager.java b/context-propagation-api/src/main/java/nl/talsmasoftware/context/api/ContextManager.java index 0d5b58b8..5f27b477 100644 --- a/context-propagation-api/src/main/java/nl/talsmasoftware/context/api/ContextManager.java +++ b/context-propagation-api/src/main/java/nl/talsmasoftware/context/api/ContextManager.java @@ -24,6 +24,7 @@ * * @param type of the context value * @author Sjoerd Talsma + * @since 2.0.0 */ public interface ContextManager { diff --git a/context-propagation-api/src/main/java/nl/talsmasoftware/context/api/ContextSnapshot.java b/context-propagation-api/src/main/java/nl/talsmasoftware/context/api/ContextSnapshot.java index 9fdc1b52..0c6da1a8 100644 --- a/context-propagation-api/src/main/java/nl/talsmasoftware/context/api/ContextSnapshot.java +++ b/context-propagation-api/src/main/java/nl/talsmasoftware/context/api/ContextSnapshot.java @@ -38,7 +38,7 @@ * {@link Reactivation#close()}. * * @author Sjoerd Talsma - * @since 1.1.0 + * @since 2.0.0 */ public interface ContextSnapshot { diff --git a/context-propagation-api/src/main/java/nl/talsmasoftware/context/api/ContextTimer.java b/context-propagation-api/src/main/java/nl/talsmasoftware/context/api/ContextTimer.java index 6fbc2d2b..7f106309 100644 --- a/context-propagation-api/src/main/java/nl/talsmasoftware/context/api/ContextTimer.java +++ b/context-propagation-api/src/main/java/nl/talsmasoftware/context/api/ContextTimer.java @@ -20,29 +20,30 @@ /** * Minimal Service Provider Interface for services that wish to get informed of context switching metrics. *

- * Currently the following timed operations are updated: + * Currently, the following timed operations are updated: *

    *
  • {@code ContextManagers.createContextSnapshot}
    • - *
  • {@code ContextSnapshot.reactivate}
    • - *
  • {@code ContextManager.initializeNewContext}(*)
    • - *
  • {@code ContextManager.getActiveContext}(*)
    • + *
  • {@linkplain ContextSnapshot#reactivate()}
    • + *
  • {@linkplain ContextManager#getActiveContextValue()} (*)
    • + *
  • {@linkplain ContextManager#initializeNewContext(Object)} (*)
    • *
*

* (*) Timing is updated for each concrete {@code ContextManager} implementation class * * @author Sjoerd Talsma - * @since 1.1.0 + * @since 2.0.0 */ public interface ContextTimer { /** * Provides a new update for the context timer. * - * @param type The class being called - * @param method The method being called - * @param duration The duration of the method - * @param unit The unit of the duration + * @param type Class that was called + * @param method Method that was called + * @param duration Duration of the call + * @param unit Unit of the duration + * @param error Error that was thrown in the call (optional, normally {@code null}) */ - void update(Class type, String method, long duration, TimeUnit unit); + void update(Class type, String method, long duration, TimeUnit unit, Throwable error); } diff --git a/context-propagation-core/src/main/java/nl/talsmasoftware/context/core/ContextManagers.java b/context-propagation-core/src/main/java/nl/talsmasoftware/context/core/ContextManagers.java index 8ae4cdae..9225bd12 100644 --- a/context-propagation-core/src/main/java/nl/talsmasoftware/context/core/ContextManagers.java +++ b/context-propagation-core/src/main/java/nl/talsmasoftware/context/core/ContextManagers.java @@ -65,15 +65,7 @@ public static ContextSnapshot createContextSnapshot() { final Object[] values = new Object[managers.size()]; for (int i = 0; i < values.length; i++) { - final ContextManager manager = managers.get(i); - long managerStart = System.nanoTime(); - try { - values[i] = getActiveContextValue(manager); - Timers.timed(System.nanoTime() - managerStart, manager.getClass(), "getActiveContext"); - } catch (RuntimeException rte) { - LOGGER.log(Level.WARNING, "Error obtaining active context from " + manager + " (in thread " + Thread.currentThread().getName() + ").", rte); - Timers.timed(System.nanoTime() - managerStart, manager.getClass(), "getActiveContext.exception"); - } + values[i] = getActiveContextValue(managers.get(i)); } final ContextSnapshotImpl result = new ContextSnapshotImpl(managers, values); @@ -82,7 +74,7 @@ public static ContextSnapshot createContextSnapshot() { + " Thead=" + Thread.currentThread() + ", ContextClassLoader=" + Thread.currentThread().getContextClassLoader()); } - Timers.timed(System.nanoTime() - start, ContextManagers.class, "createContextSnapshot"); + Timers.timed(System.nanoTime() - start, ContextManagers.class, "createContextSnapshot", null); return result; } @@ -105,24 +97,10 @@ public static ContextSnapshot createContextSnapshot() { */ public static void clearActiveContexts() { final long start = System.nanoTime(); - Long managerStart = null; for (ContextManager manager : ServiceCache.cached(ContextManager.class)) { - managerStart = System.nanoTime(); - try { - clear(manager); - Timers.timed(System.nanoTime() - managerStart, manager.getClass(), "clear"); - } catch (RuntimeException rte) { - LOGGER.log(Level.WARNING, "Error clearing active context from " + manager + ".", rte); - ServiceCache.clear(); - Timers.timed(System.nanoTime() - managerStart, manager.getClass(), "clear.exception"); - } + clear(manager); } - if (managerStart == null && LOGGER.isLoggable(Level.FINER)) { - LOGGER.finer("No ContextManagers were cleared because none were found! " - + " Thead=" + Thread.currentThread() - + ", ContextClassLoader=" + Thread.currentThread().getContextClassLoader()); - } - Timers.timed(System.nanoTime() - start, ContextManagers.class, "clearActiveContexts"); + Timers.timed(System.nanoTime() - start, ContextManagers.class, "clearActiveContexts", null); } /** @@ -151,16 +129,39 @@ public static synchronized void useClassLoader(ClassLoader classLoader) { } private static Object getActiveContextValue(ContextManager manager) { - final Object activeContextValue = manager.getActiveContextValue(); - LOGGER.finest(() -> activeContextValue == null - ? "There is no active context value for " + manager + " (in thread " + Thread.currentThread().getName() + ")." - : "Active context value of " + manager + " in " + Thread.currentThread().getName() + ": " + activeContextValue); - return activeContextValue; + final long start = System.nanoTime(); + RuntimeException error = null; + try { + + final Object activeContextValue = manager.getActiveContextValue(); + LOGGER.finest(() -> activeContextValue == null + ? "There is no active context value for " + manager + " (in thread " + Thread.currentThread().getName() + ")." + : "Active context value of " + manager + " in " + Thread.currentThread().getName() + ": " + activeContextValue); + return activeContextValue; + + } catch (RuntimeException e) { + LOGGER.log(Level.WARNING, e, () -> "Error obtaining active context from " + manager + " (in thread " + Thread.currentThread().getName() + ")."); + error = e; + return null; + } finally { + Timers.timed(System.nanoTime() - start, manager.getClass(), "getActiveContextValue", error); + } } private static void clear(ContextManager manager) { - manager.clear(); - LOGGER.finest(() -> "Active context of " + manager + " was cleared."); + final long start = System.nanoTime(); + RuntimeException error = null; + try { + + manager.clear(); + LOGGER.finest(() -> "Active context of " + manager + " was cleared."); + + } catch (RuntimeException e) { + LOGGER.log(Level.WARNING, e, () -> "Error clearing active context from " + manager + "(in thread " + Thread.currentThread().getName() + ")."); + error = e; + } finally { + Timers.timed(System.nanoTime() - start, manager.getClass(), "clear", error); + } } /** @@ -169,7 +170,6 @@ private static void clear(ContextManager manager) { */ @SuppressWarnings("rawtypes") private static final class ContextSnapshotImpl implements ContextSnapshot { - // TODO extract this inner class? private final List managers; private final Object[] values; @@ -180,49 +180,74 @@ private ContextSnapshotImpl(List managers, Object[] values) { public Reactivation reactivate() { final long start = System.nanoTime(); + RuntimeException error = null; final Context[] reactivatedContexts = new Context[managers.size()]; - try { + for (int i = 0; i < values.length; i++) { reactivatedContexts[i] = reactivate(managers.get(i), values[i]); } + return new ReactivationImpl(reactivatedContexts); - ReactivationImpl reactivation = new ReactivationImpl(reactivatedContexts); - Timers.timed(System.nanoTime() - start, ContextSnapshot.class, "reactivate"); - return reactivation; } catch (RuntimeException reactivationException) { - // TODO think about simplifying by catching & handling in reactivate(manager, value) method - for (Context alreadyReactivated : reactivatedContexts) { - if (alreadyReactivated != null) try { - if (LOGGER.isLoggable(Level.FINEST)) { - LOGGER.finest("Snapshot reactivation failed! " + - "Closing already reactivated context: " + alreadyReactivated + "."); - } - alreadyReactivated.close(); - } catch (RuntimeException rte) { - reactivationException.addSuppressed(rte); - } - } + tryClose(reactivatedContexts, reactivationException); ServiceCache.clear(); - throw reactivationException; + throw error = reactivationException; + } finally { + Timers.timed(System.nanoTime() - start, ContextSnapshot.class, "reactivate", error); } } - @SuppressWarnings("unchecked") // As we got the values from the managers themselves, they must also accept them! - private Context reactivate(ContextManager contextManager, Object snapshotValue) { - long start = System.nanoTime(); + @Override + public String toString() { + return "ContextSnapshot{size=" + managers.size() + '}'; + } + + /** + * Reactivates a snapshot value for a single context manager. + * + *

+ * This initializes a new context with the context manager + * (normally on another thread the snapshot value was captured from). + * + * @param contextManager The context manager to reactivate the snapshot value for. + * @param snapshotValue The snapshot value to be reactivated. + * @return The context to be included in the reactivation object. + */ + @SuppressWarnings("unchecked") // We got the value from the managers itself. + private static Context reactivate(ContextManager contextManager, Object snapshotValue) { if (snapshotValue == null) return null; - Context reactivated = contextManager.initializeNewContext(snapshotValue); - if (LOGGER.isLoggable(Level.FINEST)) { - LOGGER.finest("Context reactivated from snapshot by " + contextManager + ": " + reactivated + "."); + long start = System.nanoTime(); + RuntimeException error = null; + try { + + Context reactivated = contextManager.initializeNewContext(snapshotValue); + LOGGER.finest(() -> "Context reactivated from snapshot by " + contextManager + ": " + reactivated + "."); + return reactivated; + + } catch (RuntimeException e) { + throw error = e; + } finally { + Timers.timed(System.nanoTime() - start, contextManager.getClass(), "initializeNewContext", error); } - Timers.timed(System.nanoTime() - start, contextManager.getClass(), "initializeNewContext"); - return reactivated; } - @Override - public String toString() { - return "ContextSnapshot{size=" + managers.size() + '}'; + /** + * Try to close already-reactivated contexts when a later context manager threw an exception. + * + * @param reactivatedContexts The contexts that were already reactivated when the error happened. + * @param reason The error that happened. + */ + private static void tryClose(Context[] reactivatedContexts, Throwable reason) { + for (Context alreadyReactivated : reactivatedContexts) { + if (alreadyReactivated != null) { + try { + alreadyReactivated.close(); + } catch (RuntimeException rte) { + reason.addSuppressed(rte); + } + } + } } } @@ -233,7 +258,6 @@ public String toString() { */ @SuppressWarnings("rawtypes") private static final class ReactivationImpl implements Reactivation { - // TODO extract this inner class? private final Context[] reactivated; private ReactivationImpl(Context[] reactivated) { diff --git a/context-propagation-core/src/main/java/nl/talsmasoftware/context/core/Timers.java b/context-propagation-core/src/main/java/nl/talsmasoftware/context/core/Timers.java index 32c58760..0ec1366e 100644 --- a/context-propagation-core/src/main/java/nl/talsmasoftware/context/core/Timers.java +++ b/context-propagation-core/src/main/java/nl/talsmasoftware/context/core/Timers.java @@ -24,9 +24,9 @@ final class Timers { private static final Logger TIMING_LOGGER = Logger.getLogger(Timers.class.getName()); - static void timed(long durationNanos, Class type, String method) { + static void timed(long durationNanos, Class type, String method, Throwable error) { for (ContextTimer delegate : ServiceCache.cached(ContextTimer.class)) { - delegate.update(type, method, durationNanos, TimeUnit.NANOSECONDS); + delegate.update(type, method, durationNanos, TimeUnit.NANOSECONDS, error); } if (TIMING_LOGGER.isLoggable(Level.FINEST)) { TIMING_LOGGER.log(Level.FINEST, "{0}.{1}: {2,number}ns", new Object[]{type.getName(), method, durationNanos}); diff --git a/context-propagation-core/src/test/java/nl/talsmasoftware/context/core/TimersTest.java b/context-propagation-core/src/test/java/nl/talsmasoftware/context/core/TimersTest.java index 90da0c3f..a5c23ab6 100644 --- a/context-propagation-core/src/test/java/nl/talsmasoftware/context/core/TimersTest.java +++ b/context-propagation-core/src/test/java/nl/talsmasoftware/context/core/TimersTest.java @@ -34,7 +34,7 @@ public class TimersTest { @Test public void testTimingDelegation() { - Timers.timed(TimeUnit.MILLISECONDS.toNanos(150), getClass(), "testTimingDelegation"); + Timers.timed(TimeUnit.MILLISECONDS.toNanos(150), getClass(), "testTimingDelegation", null); assertThat(TestContextTimer.getLastTimedMillis(getClass(), "testTimingDelegation"), is(150L)); } @@ -45,7 +45,7 @@ public static Long getLastTimedMillis(Class type, String method) { return LAST_TIMED.get(type.getName() + "." + method); } - public void update(Class type, String method, long duration, TimeUnit unit) { + public void update(Class type, String method, long duration, TimeUnit unit, Throwable error) { LAST_TIMED.put(type.getName() + "." + method, unit.toMillis(duration)); } diff --git a/timers/context-timer-metrics/src/main/java/nl/talsmasoftware/context/timers/metrics/MetricsContextTimer.java b/timers/context-timer-metrics/src/main/java/nl/talsmasoftware/context/timers/metrics/MetricsContextTimer.java index c420bdc2..f2af09bf 100644 --- a/timers/context-timer-metrics/src/main/java/nl/talsmasoftware/context/timers/metrics/MetricsContextTimer.java +++ b/timers/context-timer-metrics/src/main/java/nl/talsmasoftware/context/timers/metrics/MetricsContextTimer.java @@ -15,6 +15,7 @@ */ package nl.talsmasoftware.context.timers.metrics; +import com.codahale.metrics.Meter; import com.codahale.metrics.MetricRegistry; import com.codahale.metrics.SharedMetricRegistries; import com.codahale.metrics.Timer; @@ -68,32 +69,45 @@ public class MetricsContextTimer implements ContextTimer { private static final String SYS_REGISTRY_NAME = "contextpropagation.metrics.registry"; private static final String ENV_REGISTRY_NAME = SYS_REGISTRY_NAME.toUpperCase().replace('.', '_'); - private static final ConcurrentMap TIMERS = new ConcurrentHashMap<>(); + private static final ConcurrentMap CACHED_TIMERS = new ConcurrentHashMap<>(); + private static final ConcurrentMap CACHED_ERRORS = new ConcurrentHashMap<>(); @Override - public void update(Class type, String method, long duration, TimeUnit unit) { - locateTimer(type, method).update(duration, unit); + public void update(Class type, String method, long duration, TimeUnit unit, Throwable error) { + final String name = MetricRegistry.name(type, method); + final String errorsName = MetricRegistry.name(name, "errors"); + CACHED_TIMERS.computeIfAbsent(name, this::registerTimer).update(duration, unit); + CACHED_ERRORS.computeIfAbsent(errorsName, this::registerMeter).mark(error == null ? 0L : 1L); } - private static Timer locateTimer(Class type, String method) { - final String name = MetricRegistry.name(type, method); - Timer timer = TIMERS.get(name); - if (timer == null) { - final Collection sharedRegistries = locateSharedRegistries(); - for (MetricRegistry registry : sharedRegistries) { - timer = registry.getTimers().get(name); - if (timer != null) break; - } - if (timer == null) timer = new Timer(); - TIMERS.putIfAbsent(name, timer); - timer = TIMERS.get(name); // In case of race conditions - for (MetricRegistry registry : sharedRegistries) { - if (!registry.getTimers().containsKey(name)) registry.register(name, timer); + private Timer registerTimer(String name) { + final Collection sharedRegistries = locateSharedRegistries(); + for (MetricRegistry registry : sharedRegistries) { + Timer timer = registry.getTimers().get(name); + if (timer != null) { + return timer; } } + + final Timer timer = new Timer(); + sharedRegistries.forEach(registry -> registry.register(name, timer)); return timer; } + private Meter registerMeter(String name) { + final Collection sharedRegistries = locateSharedRegistries(); + for (MetricRegistry registry : sharedRegistries) { + Meter meter = registry.getMeters().get(name); + if (meter != null) { + return meter; + } + } + + final Meter meter = new Meter(); + sharedRegistries.forEach(registry -> registry.register(name, meter)); + return meter; + } + private static Collection locateSharedRegistries() { String registryName = System.getProperty(SYS_REGISTRY_NAME, System.getenv(ENV_REGISTRY_NAME)); if (registryName == null) { @@ -123,6 +137,6 @@ private static Collection locateSharedRegistries() { @Override public String toString() { - return getClass().getSimpleName() + "{timers=" + TIMERS.keySet() + "}"; + return getClass().getSimpleName() + "{timers=" + CACHED_TIMERS.keySet() + "}"; } } diff --git a/timers/context-timer-metrics/src/test/java/nl/talsmasoftware/context/timers/metrics/MetricsContextTimerTest.java b/timers/context-timer-metrics/src/test/java/nl/talsmasoftware/context/timers/metrics/MetricsContextTimerTest.java index 0b4a2e54..60b10fd2 100644 --- a/timers/context-timer-metrics/src/test/java/nl/talsmasoftware/context/timers/metrics/MetricsContextTimerTest.java +++ b/timers/context-timer-metrics/src/test/java/nl/talsmasoftware/context/timers/metrics/MetricsContextTimerTest.java @@ -24,6 +24,7 @@ import org.junit.jupiter.api.Test; import java.lang.reflect.Field; +import java.util.Arrays; import java.util.Map; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicReference; @@ -47,12 +48,14 @@ public class MetricsContextTimerTest { @BeforeEach @AfterEach @SuppressWarnings("unchecked") - public void resetCacheAndRegistry() { + public void resetCachesAndRegistry() { try { - // Reflect and clear the cache - Field cache = MetricsContextTimer.class.getDeclaredField("TIMERS"); - cache.setAccessible(true); - ((Map) cache.get(null)).clear(); + // Reflect and clear the caches + for (String name : Arrays.asList("CACHED_TIMERS", "CACHED_ERRORS")) { + Field cache = MetricsContextTimer.class.getDeclaredField(name); + cache.setAccessible(true); + ((Map) cache.get(null)).clear(); + } // Clear all shared registries SharedMetricRegistries.clear(); @@ -131,7 +134,7 @@ public void testMetricsContextTimerToString() { MetricsContextTimer metricsContextTimer = new MetricsContextTimer(); assertThat(metricsContextTimer, hasToString("MetricsContextTimer{timers=[]}")); - metricsContextTimer.update(getClass(), "method", 1, TimeUnit.SECONDS); + metricsContextTimer.update(getClass(), "method", 1, TimeUnit.SECONDS, null); assertThat(metricsContextTimer, hasToString("MetricsContextTimer{timers=[" + getClass().getName() + ".method]}")); } diff --git a/timers/context-timer-micrometer/src/main/java/nl/talsmasoftware/context/timers/micrometer/MicrometerContextTimer.java b/timers/context-timer-micrometer/src/main/java/nl/talsmasoftware/context/timers/micrometer/MicrometerContextTimer.java index f5afca87..4d9e1d0b 100644 --- a/timers/context-timer-micrometer/src/main/java/nl/talsmasoftware/context/timers/micrometer/MicrometerContextTimer.java +++ b/timers/context-timer-micrometer/src/main/java/nl/talsmasoftware/context/timers/micrometer/MicrometerContextTimer.java @@ -34,9 +34,10 @@ public class MicrometerContextTimer implements ContextTimer { * @param method The method being called * @param duration The duration of the method * @param unit The unit of the duration + * @param error Optional error that occurred when calling the method. */ @Override - public void update(Class type, String method, long duration, TimeUnit unit) { + public void update(Class type, String method, long duration, TimeUnit unit, Throwable error) { Metrics.timer(type.getName() + "." + method).record(duration, unit); } diff --git a/timers/context-timer-micrometer/src/test/java/nl/talsmasoftware/context/timers/micrometer/MicrometerContextTimerTest.java b/timers/context-timer-micrometer/src/test/java/nl/talsmasoftware/context/timers/micrometer/MicrometerContextTimerTest.java index 1d11f032..2a0b66dc 100644 --- a/timers/context-timer-micrometer/src/test/java/nl/talsmasoftware/context/timers/micrometer/MicrometerContextTimerTest.java +++ b/timers/context-timer-micrometer/src/test/java/nl/talsmasoftware/context/timers/micrometer/MicrometerContextTimerTest.java @@ -61,7 +61,7 @@ public void testCreateSnapshotInFreshApplication() { @Test public void testTiming() { Timer timer = Metrics.timer(MicrometerContextTimerTest.class.getName() + ".testTiming"); - new MicrometerContextTimer().update(MicrometerContextTimerTest.class, "testTiming", 43, TimeUnit.MILLISECONDS); + new MicrometerContextTimer().update(MicrometerContextTimerTest.class, "testTiming", 43, TimeUnit.MILLISECONDS, null); assertThat(timer.count(), is(1L)); assertThat(timer.mean(TimeUnit.NANOSECONDS), closeTo(43000000.0d, 0.001d)); } diff --git a/timers/context-timer-opentracing/src/main/java/nl/talsmasoftware/context/timers/opentracing/OpentracingContextTimer.java b/timers/context-timer-opentracing/src/main/java/nl/talsmasoftware/context/timers/opentracing/OpentracingContextTimer.java index be2468b8..cb5ebd71 100644 --- a/timers/context-timer-opentracing/src/main/java/nl/talsmasoftware/context/timers/opentracing/OpentracingContextTimer.java +++ b/timers/context-timer-opentracing/src/main/java/nl/talsmasoftware/context/timers/opentracing/OpentracingContextTimer.java @@ -16,14 +16,16 @@ package nl.talsmasoftware.context.timers.opentracing; import io.opentracing.Span; +import io.opentracing.log.Fields; +import io.opentracing.tag.Tags; import io.opentracing.util.GlobalTracer; import nl.talsmasoftware.context.api.ContextSnapshot; import nl.talsmasoftware.context.api.ContextTimer; +import java.util.LinkedHashMap; +import java.util.Map; import java.util.concurrent.TimeUnit; -import static java.util.Collections.singletonMap; - /** * This {@link ContextTimer} uses the {@code Opentracing API} to report timing statistics of context switches. * @@ -35,20 +37,27 @@ public class OpentracingContextTimer implements ContextTimer { private static final String LOG_FIELD_THREAD = "context.thread"; @Override - public void update(Class type, String method, long duration, TimeUnit unit) { + public void update(Class type, String method, long duration, TimeUnit unit, Throwable error) { if (GlobalTracer.isRegistered() && reportContextSwitchesFor(type)) { String operationName = type.getSimpleName() + "." + method; long finishedMicros = System.currentTimeMillis() * 1000; long startTimestampMicros = finishedMicros - unit.toMicros(duration); Span span = GlobalTracer.get().buildSpan(operationName).withStartTimestamp(startTimestampMicros).start(); try { + Map log = new LinkedHashMap<>(); if ("createContextSnapshot".equals(method)) { - span.log("New context snapshot created"); - span.log(singletonMap(LOG_FIELD_THREAD, Thread.currentThread().getName())); + log.put(Fields.EVENT, "New context snapshot created"); } else if ("reactivate".equals(method)) { - span.log("Context snapshot reactivated"); - span.log(singletonMap(LOG_FIELD_THREAD, Thread.currentThread().getName())); + log.put(Fields.EVENT, "Context snapshot reactivated"); + } + if (error != null) { + Tags.ERROR.set(span, true); + log.put(Fields.EVENT, "error"); + log.put(Fields.MESSAGE, error.getMessage()); + log.put(Fields.ERROR_OBJECT, error); } + log.put(LOG_FIELD_THREAD, Thread.currentThread().getName()); + span.log(log); } finally { span.finish(finishedMicros); }