Skip to content

Commit d4cb46d

Browse files
schlosnaschlosna
authored
Reduce tracing overhead (#1413)
Remove unnecessary debug logging
1 parent 4807cab commit d4cb46d

File tree

2 files changed

+29
-68
lines changed

2 files changed

+29
-68
lines changed

‎changelog/@unreleased/pr-1413.v2.yml‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,5 @@
1+
type: improvement
2+
improvement:
3+
description: Remove unnecessary debug logging
4+
links:
5+
- https://github.com/palantir/tracing-java/pull/1413

‎tracing/src/main/java/com/palantir/tracing/Tracer.java‎

Lines changed: 24 additions & 68 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,7 @@
2323
import com.google.common.base.Strings;
2424
import com.google.errorprone.annotations.CheckReturnValue;
2525
import com.google.errorprone.annotations.MustBeClosed;
26+
import com.google.errorprone.annotations.concurrent.GuardedBy;
2627
import com.palantir.logsafe.Safe;
2728
import com.palantir.logsafe.SafeArg;
2829
import com.palantir.logsafe.UnsafeArg;
@@ -59,6 +60,7 @@ private Tracer() {}
5960
private static final ThreadLocal<Trace> currentTrace = new ThreadLocal<>();
6061

6162
// Only access in a class-synchronized fashion
63+
@GuardedBy("Tracer.class")
6264
private static final Map<String, SpanObserver> observers = new HashMap<>();
6365
// we want iterating through tracers to be very fast, and it's faster to pre-define observer execution
6466
// when our observers are modified.
@@ -389,13 +391,8 @@ static boolean isSampled(DetachedSpan detachedSpan) {
389391
return detachedSpan instanceof SampledDetachedSpan;
390392
}
391393

392-
private static final class TraceRestoringCloseableSpanWithMetadata<T> implements CloseableSpan {
393-
394-
@Nullable
395-
private final Trace original;
396-
397-
private final TagTranslator<? super T> translator;
398-
private final T data;
394+
private record TraceRestoringCloseableSpanWithMetadata<T>(
395+
@Nullable Trace original, TagTranslator<? super T> translator, T data) implements CloseableSpan {
399396

400397
static <T> CloseableSpan of(@Nullable Trace original, TagTranslator<? super T> translator, T data) {
401398
if (original != null || !translator.isEmpty(data)) {
@@ -404,12 +401,6 @@ static <T> CloseableSpan of(@Nullable Trace original, TagTranslator<? super T> t
404401
return DEFAULT_CLOSEABLE_SPAN;
405402
}
406403

407-
TraceRestoringCloseableSpanWithMetadata(@Nullable Trace original, TagTranslator<? super T> translator, T data) {
408-
this.original = original;
409-
this.translator = translator;
410-
this.data = data;
411-
}
412-
413404
@Override
414405
public void close() {
415406
Tracer.fastCompleteSpan(translator, data);
@@ -509,15 +500,7 @@ public String toString() {
509500
}
510501
}
511502

512-
private static final class SampledDetached implements Detached {
513-
514-
private final TraceState traceState;
515-
private final OpenSpan openSpan;
516-
517-
SampledDetached(TraceState traceState, OpenSpan openSpan) {
518-
this.traceState = traceState;
519-
this.openSpan = openSpan;
520-
}
503+
private record SampledDetached(TraceState traceState, OpenSpan openSpan) implements Detached {
521504

522505
@Override
523506
@MustBeClosed
@@ -543,15 +526,7 @@ public String toString() {
543526
}
544527
}
545528

546-
private static final class UnsampledDetachedSpan implements DetachedSpan {
547-
548-
private final TraceState traceState;
549-
private final Optional<String> parentSpanId;
550-
551-
UnsampledDetachedSpan(TraceState traceState, Optional<String> parentSpanId) {
552-
this.traceState = traceState;
553-
this.parentSpanId = parentSpanId;
554-
}
529+
private record UnsampledDetachedSpan(TraceState traceState, Optional<String> parentSpanId) implements DetachedSpan {
555530

556531
@Override
557532
public <T> CloseableSpan childSpan(
@@ -601,14 +576,7 @@ public String toString() {
601576
private static final CloseableSpan DEFAULT_CLOSEABLE_SPAN = Tracer::fastCompleteSpan;
602577
private static final CloseableSpan REMOVE_TRACE = Tracer::clearCurrentTrace;
603578

604-
private static final class TraceRestoringCloseableSpan implements CloseableSpan {
605-
606-
private final Trace original;
607-
608-
TraceRestoringCloseableSpan(Trace original) {
609-
this.original = original;
610-
}
611-
579+
private record TraceRestoringCloseableSpan(Trace original) implements CloseableSpan {
612580
@Override
613581
public void close() {
614582
Tracer.fastCompleteSpan();
@@ -640,11 +608,8 @@ public static <T> void fastCompleteSpan(TagTranslator<? super T> tag, T state) {
640608
if (trace.isObservable()) {
641609
completeSpanAndNotifyObservers(span, tag, state, trace.getTraceId());
642610
}
643-
} else if (log.isDebugEnabled()) {
644-
log.debug(
645-
"Attempted to complete spans when there is no active Trace. This may be the "
646-
+ "result of calling completeSpan more times than startSpan",
647-
new SafeRuntimeException("not a real exception"));
611+
} else {
612+
logCompletedWithoutStarted();
648613
}
649614
}
650615

@@ -676,12 +641,7 @@ public static Optional<Span> completeSpan() {
676641
public static Optional<Span> completeSpan(@Safe Map<String, String> metadata) {
677642
Trace trace = currentTrace.get();
678643
if (trace == null) {
679-
if (log.isDebugEnabled()) {
680-
log.debug(
681-
"Attempted to complete spans when there is no active Trace. This may be the "
682-
+ "result of calling completeSpan more times than startSpan",
683-
new SafeRuntimeException("not a real exception"));
684-
}
644+
logCompletedWithoutStarted();
685645
return Optional.empty();
686646
}
687647
Optional<Span> maybeSpan = popCurrentSpan(trace)
@@ -696,6 +656,15 @@ public static Optional<Span> completeSpan(@Safe Map<String, String> metadata) {
696656
return maybeSpan;
697657
}
698658

659+
private static void logCompletedWithoutStarted() {
660+
if (log.isDebugEnabled()) {
661+
log.debug(
662+
"Attempted to complete spans when there is no active Trace."
663+
+ " This may be the result of calling completeSpan more times than startSpan",
664+
new SafeRuntimeException("not a real exception"));
665+
}
666+
}
667+
699668
private static void notifyObservers(Span span) {
700669
compositeObserver.accept(span);
701670
}
@@ -745,8 +714,10 @@ public void tag(Span.Builder target, Map<String, String> tags) {
745714
* registered for the given name, then it gets overwritten by this call. Returns the observer previously associated
746715
* with the given name, or null if there is no such observer.
747716
*/
717+
@Nullable
748718
public static synchronized SpanObserver subscribe(String name, SpanObserver observer) {
749-
if (observers.containsKey(name)) {
719+
SpanObserver currentValue = observers.put(name, observer);
720+
if (currentValue != null) {
750721
log.warn(
751722
"Overwriting existing SpanObserver with name {} by new observer: {}",
752723
SafeArg.of("name", name),
@@ -755,7 +726,6 @@ public static synchronized SpanObserver subscribe(String name, SpanObserver obse
755726
if (observers.size() >= 5) {
756727
log.warn("Five or more SpanObservers registered: {}", SafeArg.of("observers", observers.keySet()));
757728
}
758-
SpanObserver currentValue = observers.put(name, observer);
759729
computeObserversList();
760730
return currentValue;
761731
}
@@ -770,6 +740,7 @@ public static synchronized SpanObserver unsubscribe(String name) {
770740
return removedObserver;
771741
}
772742

743+
@GuardedBy("Tracer.class")
773744
private static void computeObserversList() {
774745
Consumer<Span> newCompositeObserver = _span -> {};
775746
for (Map.Entry<String, SpanObserver> entry : observers.entrySet()) {
@@ -892,8 +863,6 @@ static void setTrace(Trace trace) {
892863
MDC.put(Tracers.TRACE_ID_KEY, trace.getTraceId());
893864
setTraceSampledMdcIfObservable(trace.isObservable());
894865
setTraceRequestId(trace.maybeGetRequestId());
895-
896-
logSettingTrace();
897866
}
898867

899868
private static void setTraceSampledMdcIfObservable(boolean observable) {
@@ -915,10 +884,6 @@ private static void setTraceRequestId(@Nullable String requestId) {
915884
}
916885
}
917886

918-
private static void logSettingTrace() {
919-
log.debug("Setting trace");
920-
}
921-
922887
private static Trace getOrCreateCurrentTrace() {
923888
Trace trace = currentTrace.get();
924889
if (trace == null) {
@@ -930,19 +895,10 @@ private static Trace getOrCreateCurrentTrace() {
930895

931896
@VisibleForTesting
932897
static void clearCurrentTrace() {
933-
logClearingTrace();
898+
//noinspection ThreadLocalSetWithNull explicitly not removing thread local to avoid churn, see PR #849
934899
currentTrace.set(null);
935900
MDC.remove(Tracers.TRACE_ID_KEY);
936901
MDC.remove(Tracers.TRACE_SAMPLED_KEY);
937902
MDC.remove(Tracers.REQUEST_ID_KEY);
938903
}
939-
940-
private static void logClearingTrace() {
941-
if (log.isDebugEnabled()) {
942-
log.debug("Clearing current trace", SafeArg.of("trace", currentTrace.get()));
943-
if (log.isTraceEnabled()) {
944-
log.trace("Stacktrace at time of clearing trace", new SafeRuntimeException("not a real exception"));
945-
}
946-
}
947-
}
948904
}

0 commit comments

Comments
 (0)