From 636f8fbeda5a069e03d3d255378fbc7db0c11a39 Mon Sep 17 00:00:00 2001 From: Jonas Kunz Date: Fri, 2 Oct 2020 09:46:12 +0200 Subject: [PATCH] Closes #459 - Implemented stack trace sampling (#930) --- .../tracing/AutoTracingTest.java | 70 ++++ .../resources/config/AutoTracingTest.yml | 22 ++ .../rules/RuleTracingSettings.java | 14 + .../model/tracing/AutoTracingSettings.java | 31 ++ .../config/model/tracing/TracingSettings.java | 7 +- .../ocelot/config/default/basics.yml | 4 + .../rules/http/apache-client/tracing.yml | 1 + .../rules/http/httpurlconnection/tracing.yml | 2 + inspectit-ocelot-core/build.gradle | 1 + .../autotracing/CustomSpanBuilder.java | 193 ++++++++++ .../autotracing/Invocation.java | 179 +++++++++ .../autotracing/InvocationResolver.java | 268 +++++++++++++ .../autotracing/PlaceholderSpan.java | 128 +++++++ .../autotracing/SampledTrace.java | 248 ++++++++++++ .../autotracing/StackTrace.java | 136 +++++++ .../autotracing/StackTraceSampler.java | 316 ++++++++++++++++ .../autotracing/events/MethodEntryEvent.java | 71 ++++ .../autotracing/events/MethodExitEvent.java | 28 ++ .../events/StackTraceSampledEvent.java | 22 ++ .../autotracing/events/TraceEvent.java | 40 ++ .../MethodHookConfigurationResolver.java | 51 ++- .../context/InspectitContextImpl.java | 24 +- .../hook/MethodHookGenerator.java | 18 + .../span/ContinueOrStartSpanAction.java | 48 +-- .../ocelot/core/utils/HighPrecisionTimer.java | 190 ++++++++++ .../autotracing/CustomSpanBuilderTest.java | 41 ++ .../autotracing/SampledTraceTest.java | 355 ++++++++++++++++++ .../autotracing/StackTraceTest.java | 52 +++ .../context/InspectitContextImplTest.java | 6 +- .../core/util/HighPrecisionTimerTest.java | 91 +++++ .../docs/breaking-changes/1.6.md | 6 + .../docs/instrumentation/rules.md | 45 ++- .../website/sidebars.json | 1 + 33 files changed, 2646 insertions(+), 63 deletions(-) create mode 100644 inspectit-ocelot-agent/src/system-test/java/rocks/inspectit/ocelot/instrumentation/tracing/AutoTracingTest.java create mode 100644 inspectit-ocelot-agent/src/system-test/resources/config/AutoTracingTest.yml create mode 100644 inspectit-ocelot-config/src/main/java/rocks/inspectit/ocelot/config/model/tracing/AutoTracingSettings.java create mode 100644 inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/CustomSpanBuilder.java create mode 100644 inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/Invocation.java create mode 100644 inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/InvocationResolver.java create mode 100644 inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/PlaceholderSpan.java create mode 100644 inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/SampledTrace.java create mode 100644 inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/StackTrace.java create mode 100644 inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/StackTraceSampler.java create mode 100644 inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/events/MethodEntryEvent.java create mode 100644 inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/events/MethodExitEvent.java create mode 100644 inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/events/StackTraceSampledEvent.java create mode 100644 inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/events/TraceEvent.java create mode 100644 inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/utils/HighPrecisionTimer.java create mode 100644 inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/CustomSpanBuilderTest.java create mode 100644 inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/SampledTraceTest.java create mode 100644 inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/StackTraceTest.java create mode 100644 inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/util/HighPrecisionTimerTest.java create mode 100644 inspectit-ocelot-documentation/docs/breaking-changes/1.6.md diff --git a/inspectit-ocelot-agent/src/system-test/java/rocks/inspectit/ocelot/instrumentation/tracing/AutoTracingTest.java b/inspectit-ocelot-agent/src/system-test/java/rocks/inspectit/ocelot/instrumentation/tracing/AutoTracingTest.java new file mode 100644 index 0000000000..68377d291b --- /dev/null +++ b/inspectit-ocelot-agent/src/system-test/java/rocks/inspectit/ocelot/instrumentation/tracing/AutoTracingTest.java @@ -0,0 +1,70 @@ +package rocks.inspectit.ocelot.instrumentation.tracing; + +import io.opencensus.trace.export.SpanData; +import org.junit.jupiter.api.BeforeAll; +import org.junit.jupiter.api.Test; +import rocks.inspectit.ocelot.utils.TestUtils; + +import java.util.Collection; +import java.util.Optional; +import java.util.concurrent.TimeUnit; + +import static org.assertj.core.api.Assertions.assertThat; + +public class AutoTracingTest extends TraceTestBase { + + @BeforeAll + static void waitForInstrumentation() { + TestUtils.waitForClassInstrumentation(AutoTracingTest.class, true, 30, TimeUnit.SECONDS); + } + + SpanData getSpanWithName(Collection spans, String name) { + Optional spanOptional = spans.stream() + .filter(s -> ((SpanData) s).getName().equals(name)) + .findFirst(); + assertThat(spanOptional).isNotEmpty(); + return spanOptional.get(); + } + + @Test + void verifyStackTraceSampling() { + instrumentMe(); + + assertTraceExported((spans) -> { + + SpanData root = getSpanWithName(spans, "AutoTracingTest.instrumentMe"); + SpanData activeWait = getSpanWithName(spans, "*AutoTracingTest.activeWait"); + SpanData passiveWait = getSpanWithName(spans, "*Thread.sleep"); + + assertThat(activeWait.getParentSpanId()).isEqualTo(root.getContext().getSpanId()); + assertThat(passiveWait.getParentSpanId()).isEqualTo(root.getContext().getSpanId()); + + assertThat(activeWait.getEndTimestamp()).isLessThan(passiveWait.getStartTimestamp()); + }); + } + + private void passiveWait(long duration) { + try { + Thread.sleep(duration); + } catch (InterruptedException e) { + throw new RuntimeException(e); + } + } + + private void activeWait(long duration) { + long durationNanos = duration * 1000 * 1000; + long start = System.nanoTime(); + while ((System.nanoTime() - start) < durationNanos) { + } + } + + private void nestedWait(long duration) { + passiveWait(duration); + } + + private void instrumentMe() { + activeWait(150); + nestedWait(100); + } + +} diff --git a/inspectit-ocelot-agent/src/system-test/resources/config/AutoTracingTest.yml b/inspectit-ocelot-agent/src/system-test/resources/config/AutoTracingTest.yml new file mode 100644 index 0000000000..d0962239e3 --- /dev/null +++ b/inspectit-ocelot-agent/src/system-test/resources/config/AutoTracingTest.yml @@ -0,0 +1,22 @@ + +inspectit: + tracing: + auto-tracing: + frequency: 10ms + instrumentation: + + scopes: + AutoTracingTest-instrumentMe: + type: + name: AutoTracingTest + matcher-mode: ENDS_WITH + methods: + - name: instrumentMe + + rules: + AutoTracingTest-instrumentMe: + scopes: + AutoTracingTest-instrumentMe: true + tracing: + start-span: true + auto-tracing: true \ No newline at end of file diff --git a/inspectit-ocelot-config/src/main/java/rocks/inspectit/ocelot/config/model/instrumentation/rules/RuleTracingSettings.java b/inspectit-ocelot-config/src/main/java/rocks/inspectit/ocelot/config/model/instrumentation/rules/RuleTracingSettings.java index 54392cd02e..e76a68a977 100644 --- a/inspectit-ocelot-config/src/main/java/rocks/inspectit/ocelot/config/model/instrumentation/rules/RuleTracingSettings.java +++ b/inspectit-ocelot-config/src/main/java/rocks/inspectit/ocelot/config/model/instrumentation/rules/RuleTracingSettings.java @@ -46,6 +46,20 @@ public class RuleTracingSettings { */ private String continueSpan; + /** + * Enables or disables auto-tracing (=stack trace sampling). + * If this field is set to true, all sub-invocations of the instrumented method will be traced via stack-trace sampling. + * This only takes effect if either {@link #startSpan} or {@link #continueSpan} is configured and the current method is actually traced. + *

+ * In addition this field can be set to false. In this case if any parent method has started a stack-trace sampling session, + * it will be paused for the duration of this method. + * This means effectively children of this method will be excluded from being traced using stack trace sampling. + *

+ * If this field is null (the default value), no changes will be made to the current threads sampling session: + * If a parent has started a sampling session, it will be continued. If no sampling has been activated, none will be started. + */ + private Boolean autoTracing; + /** * If not null, the span started or continued by this rule will be stored under the given data key. */ diff --git a/inspectit-ocelot-config/src/main/java/rocks/inspectit/ocelot/config/model/tracing/AutoTracingSettings.java b/inspectit-ocelot-config/src/main/java/rocks/inspectit/ocelot/config/model/tracing/AutoTracingSettings.java new file mode 100644 index 0000000000..0e0d2ad128 --- /dev/null +++ b/inspectit-ocelot-config/src/main/java/rocks/inspectit/ocelot/config/model/tracing/AutoTracingSettings.java @@ -0,0 +1,31 @@ +package rocks.inspectit.ocelot.config.model.tracing; + +import lombok.Data; +import lombok.NoArgsConstructor; + +import java.time.Duration; + +/** + * Defines global settings regarding the stack trace sampling feature. + */ +@Data +@NoArgsConstructor +public class AutoTracingSettings { + + /** + * Defines the frequency at which stack trace samples are taken. + * The higher the frequency, the greater the accuracy of the resulting trace. + *

+ * However, taking stack traces is very expensive, therefore high frequencies can induce a big performance penalty. + */ + private Duration frequency; + + /** + * When the first method executes with auto-tracing enabled, a separate Thread is started as a timer for taking stack trace samples. + * If at some point no more methods with stack-trace sampling are executed, this thread spins unnecessarily. + *

+ * Therefore if no samples has been taken for at least the duration of {@link #shutdownDelay}, the timer will be shutdown. + * If a span requests sampling after the timer has shutdown, it will restart it. + */ + private Duration shutdownDelay; +} diff --git a/inspectit-ocelot-config/src/main/java/rocks/inspectit/ocelot/config/model/tracing/TracingSettings.java b/inspectit-ocelot-config/src/main/java/rocks/inspectit/ocelot/config/model/tracing/TracingSettings.java index 397a29f256..fe5d36dcd9 100644 --- a/inspectit-ocelot-config/src/main/java/rocks/inspectit/ocelot/config/model/tracing/TracingSettings.java +++ b/inspectit-ocelot-config/src/main/java/rocks/inspectit/ocelot/config/model/tracing/TracingSettings.java @@ -44,13 +44,18 @@ public enum AddCommonTags { @Valid private LogCorrelationSettings logCorrelation = new LogCorrelationSettings(); - /** * Generically defines behavior of adding common tags to spans. */ @NotNull private AddCommonTags addCommonTags; + /** + * Settings for automatic tracing (stack trace sampling) + */ + @Valid + private AutoTracingSettings autoTracing; + /** * The propagation format to use. */ diff --git a/inspectit-ocelot-config/src/main/resources/rocks/inspectit/ocelot/config/default/basics.yml b/inspectit-ocelot-config/src/main/resources/rocks/inspectit/ocelot/config/default/basics.yml index 01ce56833b..c63e7b9fb6 100644 --- a/inspectit-ocelot-config/src/main/resources/rocks/inspectit/ocelot/config/default/basics.yml +++ b/inspectit-ocelot-config/src/main/resources/rocks/inspectit/ocelot/config/default/basics.yml @@ -34,6 +34,10 @@ inspectit: # defines when to add common tags as attributes to spans # options are: NEVER, ON_GLOBAL_ROOT, ON_LOCAL_ROOT, ALWAYS add-common-tags: ON_LOCAL_ROOT + # settings regarding automatic tracing (stack-trace-sampling) + auto-tracing: + frequency: 50ms + shutdown-delay: 30s # settings regarding log correlation log-correlation: trace-id-mdc-injection: diff --git a/inspectit-ocelot-config/src/main/resources/rocks/inspectit/ocelot/config/default/instrumentation/rules/http/apache-client/tracing.yml b/inspectit-ocelot-config/src/main/resources/rocks/inspectit/ocelot/config/default/instrumentation/rules/http/apache-client/tracing.yml index 2e045e0934..ae7158cb1b 100644 --- a/inspectit-ocelot-config/src/main/resources/rocks/inspectit/ocelot/config/default/instrumentation/rules/http/apache-client/tracing.yml +++ b/inspectit-ocelot-config/src/main/resources/rocks/inspectit/ocelot/config/default/instrumentation/rules/http/apache-client/tracing.yml @@ -12,6 +12,7 @@ inspectit: 's_apacheclient_doExecute': true tracing: start-span: true + auto-tracing: false kind: CLIENT start-span-conditions: only-if-true: 'http_is_entry' diff --git a/inspectit-ocelot-config/src/main/resources/rocks/inspectit/ocelot/config/default/instrumentation/rules/http/httpurlconnection/tracing.yml b/inspectit-ocelot-config/src/main/resources/rocks/inspectit/ocelot/config/default/instrumentation/rules/http/httpurlconnection/tracing.yml index 15c931bcb1..c0980add0b 100644 --- a/inspectit-ocelot-config/src/main/resources/rocks/inspectit/ocelot/config/default/instrumentation/rules/http/httpurlconnection/tracing.yml +++ b/inspectit-ocelot-config/src/main/resources/rocks/inspectit/ocelot/config/default/instrumentation/rules/http/httpurlconnection/tracing.yml @@ -13,6 +13,7 @@ inspectit: 's_httpurlconnection_getOutputStream': true tracing: start-span: true + auto-tracing: false start-span-conditions: only-if-true: 'httpurlconnection_is_start' end-span: false @@ -42,6 +43,7 @@ inspectit: 's_httpurlconnection_requestInitiators': true tracing: start-span: true + auto-tracing: false continue-span: 'httpurlconnection_span' continue-span-conditions: only-if-true: 'httpurlconnection_is_end' diff --git a/inspectit-ocelot-core/build.gradle b/inspectit-ocelot-core/build.gradle index 5da66bf817..72b1966b19 100644 --- a/inspectit-ocelot-core/build.gradle +++ b/inspectit-ocelot-core/build.gradle @@ -22,6 +22,7 @@ dependencies { compileOnly( project(':inspectit-ocelot-bootstrap'), "io.opencensus:opencensus-api:${openCensusVersion}", + "io.opencensus:opencensus-impl:${openCensusVersion}", 'org.projectlombok:lombok:1.18.12' ) buildTools( diff --git a/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/CustomSpanBuilder.java b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/CustomSpanBuilder.java new file mode 100644 index 0000000000..a4673faa43 --- /dev/null +++ b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/CustomSpanBuilder.java @@ -0,0 +1,193 @@ +package rocks.inspectit.ocelot.core.instrumentation.autotracing; + +import io.opencensus.common.Clock; +import io.opencensus.common.Timestamp; +import io.opencensus.implcore.internal.TimestampConverter; +import io.opencensus.implcore.trace.RecordEventsSpanImpl; +import io.opencensus.implcore.trace.TracerImpl; +import io.opencensus.trace.Span; +import io.opencensus.trace.SpanContext; +import io.opencensus.trace.SpanId; +import io.opencensus.trace.Tracing; +import io.opencensus.trace.config.TraceParams; +import lombok.Setter; + +import java.lang.reflect.Field; +import java.util.Random; + +/** + * Allows building of spans with custom timestamps. + */ +public class CustomSpanBuilder { + + /** + * The options member of {@link TracerImpl}. + */ + private static final Field TRACERIMPL_OPTIONS; + + /** + * The startEndHandler member of {@link io.opencensus.implcore.trace.SpanBuilderImpl.Options}. + */ + private static final Field SPANBUILDEROPTIONS_STARTENDHANDLER; + + /** + * The timestampConverter member of {@link io.opencensus.implcore.trace.RecordEventsSpanImpl}. + */ + private static final Field RECORDEVENTSSPANIMPL_TIMESTAMPCONVERTER; + + /** + * Random used to generate span IDs. + */ + private static final Random RANDOM = new Random(); + + /** + * The span to use as parent. + */ + private Span parent; + + /** + * The name to use for the span. + */ + private String name; + + /** + * The spanId to use, null if it should be autogenerated. + */ + private SpanId spanId; + + /** + * The timestamp converter to use for the overriden timestamp {@link #entryNanos} and {@link #exitNanos}. + */ + private TimestampConverter converter; + + /** + * The span kind to assign to the span. + */ + private Span.Kind kind; + + /** + * The timestamps to use for the new span. If not set, the span takes times as usual. + */ + private long entryNanos = 0; + + private long exitNanos = 0; + + static { + try { + TRACERIMPL_OPTIONS = TracerImpl.class.getDeclaredField("spanBuilderOptions"); + TRACERIMPL_OPTIONS.setAccessible(true); + Class spanBuilderOptionsClass = TRACERIMPL_OPTIONS.get(Tracing.getTracer()).getClass(); + SPANBUILDEROPTIONS_STARTENDHANDLER = spanBuilderOptionsClass.getDeclaredField("startEndHandler"); + SPANBUILDEROPTIONS_STARTENDHANDLER.setAccessible(true); + + RECORDEVENTSSPANIMPL_TIMESTAMPCONVERTER = RecordEventsSpanImpl.class.getDeclaredField("timestampConverter"); + RECORDEVENTSSPANIMPL_TIMESTAMPCONVERTER.setAccessible(true); + } catch (Exception e) { + throw new RuntimeException(e); + } + } + + private CustomSpanBuilder(String name, Span parent) { + this.parent = parent; + this.name = name; + } + + /** + * Utility method for extracting a timestamp-converter from a given span. + * + * @param span the span to extract the converter from. + * + * @return the extracted converter. + */ + public static TimestampConverter getTimestampConverter(RecordEventsSpanImpl span) { + try { + return (TimestampConverter) RECORDEVENTSSPANIMPL_TIMESTAMPCONVERTER.get(span); + } catch (IllegalAccessException e) { + throw new IllegalStateException("Could not extract timestamp converter", e); + } + } + + public static CustomSpanBuilder builder(String name, Span parent) { + return new CustomSpanBuilder(name, parent); + } + + /** + * Replaces the timings on the resulting Span. + * A timestamp converter must be given if the parent is not a sampled span, otherwise it can be null. + * + * @param entryNanos the nano entry timestamp + * @param exitNanos the nano exit timestamp + * @param converter the timestamp converter to use, if null it will be derived from the parent span. + * + * @return the builder + */ + public CustomSpanBuilder customTiming(long entryNanos, long exitNanos, TimestampConverter converter) { + if (converter == null) { + if ((parent instanceof RecordEventsSpanImpl)) { + this.converter = getTimestampConverter((RecordEventsSpanImpl) parent); + } else { + throw new IllegalArgumentException("converter may only be null if the parent is a RecordEventsSpanImpl"); + } + } else { + this.converter = converter; + } + this.entryNanos = entryNanos; + this.exitNanos = exitNanos; + return this; + } + + public CustomSpanBuilder spanId(SpanId id) { + spanId = id; + return this; + } + + public CustomSpanBuilder kind(Span.Kind kind) { + this.kind = kind; + return this; + } + + public Span startSpan() { + SpanContext parentContext = parent.getContext(); + TraceParams params = Tracing.getTraceConfig().getActiveTraceParams(); + SpanId id = spanId != null ? spanId : SpanId.generateRandomId(RANDOM); + + SpanContext context = SpanContext.create(parentContext.getTraceId(), id, parentContext.getTraceOptions(), parentContext + .getTracestate()); + + if (entryNanos != 0) { + DummyClock clock = new DummyClock(); + clock.setValue(entryNanos); + RecordEventsSpanImpl result = RecordEventsSpanImpl.startSpan(context, name, kind, parentContext.getSpanId(), false, params, getStartEndHandler(), converter, clock); + clock.setValue(exitNanos); + return result; + } else { + Clock clock = Tracing.getClock(); + return RecordEventsSpanImpl.startSpan(context, name, kind, parentContext.getSpanId(), false, params, getStartEndHandler(), converter, clock); + } + } + + private static RecordEventsSpanImpl.StartEndHandler getStartEndHandler() { + try { + Object options = TRACERIMPL_OPTIONS.get(Tracing.getTracer()); + return (RecordEventsSpanImpl.StartEndHandler) SPANBUILDEROPTIONS_STARTENDHANDLER.get(options); + } catch (IllegalAccessException e) { + throw new IllegalStateException("Could not extract start/end handler", e); + } + } + + private static class DummyClock extends Clock { + + @Setter + private long value; + + @Override + public Timestamp now() { + throw new UnsupportedOperationException(); + } + + @Override + public long nowNanos() { + return value; + } + } +} diff --git a/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/Invocation.java b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/Invocation.java new file mode 100644 index 0000000000..0a46037599 --- /dev/null +++ b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/Invocation.java @@ -0,0 +1,179 @@ +package rocks.inspectit.ocelot.core.instrumentation.autotracing; + +import io.opencensus.trace.Span; +import lombok.Getter; +import rocks.inspectit.ocelot.core.instrumentation.autotracing.events.TraceEvent; + +import java.util.Iterator; + +/** + * After a trace is reconstructed from a lsit of {@link TraceEvent}, + * the individual method calls are represented by an {@link Invocation} each. + *

+ * Afterwards, only a subset of {@link Invocation} are exported as actual spans, + * based on the {@link #isHidden()} value. + */ +public class Invocation { + + /** + * The event defining when this method invocation started. + * The timestamp of the event corresponds to point in time when the invocation was started. + */ + @Getter + private TraceEvent start; + + /** + * The event defining when this method invocation ended. + * The timestamp of the event corresponds to point in time when the invocation was finished. + */ + @Getter + private TraceEvent end; + + /** + * If this method invocation was reconstructed from stack-trace-samples, + * this field stores a stack-trace element identifying this method. + * It is guaranteed that either {@link #sampledMethod}, {@link #placeholderSpan} or {@link #continuedSpan} are not null. + */ + @Getter + private StackTraceElement sampledMethod; + + /** + * If this method invocation was recorded due to instrumentation AND a new span was started for this + * invocation, it is stored in this field. + * It is guaranteed that either {@link #sampledMethod}, {@link #placeholderSpan} or {@link #continuedSpan} are not null. + */ + @Getter + private PlaceholderSpan placeholderSpan; + + /** + * If this method invocation was recorded due to instrumentation AND an existing span was continued, + * it is stored in this field. + * It is guaranteed that either {@link #sampledMethod}, {@link #placeholderSpan} or {@link #continuedSpan} are not null. + */ + @Getter + private Span continuedSpan; + + //------Linked List of children:-------------- + + /** + * Stored the invocation which happened directly after this invocation. + * This implies that nextSibling has the same parent. + * This field acts as a single linked list pointer for the list of children of the parent. + */ + private Invocation nextSibling = null; + + /** + * Pointer to the start of the linked list of children. + */ + @Getter + private Invocation firstChild = null; + + /** + * Pointer to the end of the linked list of children. + */ + @Getter + private Invocation lastChild = null; + + /** + * Pointer to the parent of this Invocation, if it has any. + */ + @Getter + private Invocation parent = null; + + /** + * Constructs a Invocation representing an instrumented method call. + * Exactly one of placeholderSpan or continuedSpan must not be null. + * + * @param start the event when the call started + * @param end the event when the call ended + * @param placeholderSpan if this method started a new span, this is its placeholder. + * @param continuedSpan if this method continued an existing span, this is the span which was continued. + */ + public Invocation(TraceEvent start, TraceEvent end, PlaceholderSpan placeholderSpan, Span continuedSpan) { + this.start = start; + this.end = end; + this.placeholderSpan = placeholderSpan; + this.continuedSpan = continuedSpan; + } + + /** + * Construct a Invocation representing a method call which was reconstructed based on stack trace samples. + * + * @param start the start of this method call + * @param end the end of this method call. + * @param method + */ + public Invocation(TraceEvent start, TraceEvent end, StackTraceElement method) { + this.start = start; + this.end = end; + sampledMethod = method; + } + + /** + * Appends the given invocation to the end of the list of children. + * + * @param child the child to add. + */ + public void addChild(Invocation child) { + child.parent = this; + if (firstChild == null) { + firstChild = child; + } + if (lastChild != null) { + lastChild.nextSibling = child; + } + lastChild = child; + } + + public Iterable getChildren() { + return () -> new ChildIterator(firstChild); + } + + /** + * To preserve clarity of exported traces, we "hide" certain invocations, meaning that they will not be exported. + * We hide invocation which fullfill all of the following conditions: + * - the invocation was generated based on stack trace samples (and NOT via instrumentation!) + * - the invocation has exactly one child-invocation + * - the start and end of the invocation matches it's only child + * + * @return true, if this invocaiton should be hidden when exported. + */ + public boolean isHidden() { + if (sampledMethod == null) { + return false; + } + //must have exactly one child + if (firstChild == null || firstChild != lastChild) { + return false; + } + if (firstChild.start != start || firstChild.end != end) { + return false; + } + return true; + } + + /** + * Iterator for iterating over the linked list of children. + */ + private static class ChildIterator implements Iterator { + + private Invocation current; + + ChildIterator(Invocation first) { + current = first; + } + + @Override + public boolean hasNext() { + return current != null; + } + + @Override + public Invocation next() { + Invocation next = current; + current = current.nextSibling; + return next; + } + } + +} diff --git a/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/InvocationResolver.java b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/InvocationResolver.java new file mode 100644 index 0000000000..f4c5cc0cfe --- /dev/null +++ b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/InvocationResolver.java @@ -0,0 +1,268 @@ +package rocks.inspectit.ocelot.core.instrumentation.autotracing; + +import rocks.inspectit.ocelot.core.instrumentation.autotracing.events.MethodEntryEvent; +import rocks.inspectit.ocelot.core.instrumentation.autotracing.events.MethodExitEvent; +import rocks.inspectit.ocelot.core.instrumentation.autotracing.events.TraceEvent; + +import java.util.*; + +/** + * This class contains the algorithm for converting a series of {@link TraceEvent}s + * into a tree of {@link Invocation}s. + */ +public class InvocationResolver { + + /** + * Reconstructs a tree of {@link Invocation}s from the given series of events. + * + * @param events the list of events (stack trace samples, method entry and exists) in the order they were recorded in time + * @param rootStackTraceDepth the depth at which the root-method of this trace is located within the stack-traces. + * + * @return an ordered list of Invocations representing all method calls at the level rootStackTraceDepth+1 (=the children of the root method) + */ + public static Iterable convertEventsToInvocations(List events, int rootStackTraceDepth) { + Map durations = getMethodDurations(events); + List enhancedEvents = new ArrayList<>(); + assignStackTracesToMethodEntries(events, durations, rootStackTraceDepth + 1, enhancedEvents); + if (events.size() != enhancedEvents.size()) { + throw new IllegalStateException("Something went wrong!"); + } + + Invocation rootInvocation = new Invocation(null, null, null); //dummy object, just used as a list + resolveChildInvocations(enhancedEvents, rootStackTraceDepth + 1, rootInvocation); + return rootInvocation.getChildren(); + } + + /** + * In order to better locate the instrumented methods between the sampled ones, + * we need to have a stack trace for each method entry event. + *

+ * This function does this for each instrumented method by checking if any stack trace + * was recorded between the start and the end of the method. + * By nature, this stack-trace will contain the instrumented method itself. + * Therefore we search the stack trace for the method and remove all frames below it. + * This new stack trace can then be used as stack trace for the method. + * + * @param events the input events to analyze + * @param durations an index for the method durations (computed via {@link #getMethodDurations(List)} + * @param startDepth the depth at which we start looking for the methods within the stack traces. + * @param output All events from the "events" argument will be appended to this output list, but possibly enhanced with better stack traces. + */ + private static void assignStackTracesToMethodEntries(List events, Map durations, int startDepth, List output) { + int offset = 0; + while (offset < events.size()) { + TraceEvent origEvent = events.get(offset); + if (origEvent instanceof MethodEntryEvent) { + MethodEntryEvent entryEvent = (MethodEntryEvent) origEvent; + int duration = durations.get(origEvent); + MethodExitEvent exitEvent = (MethodExitEvent) events.get(offset + duration); + //only consider events between start and end of the method + List methodEvents = events.subList(offset, offset + duration + 1); + Optional firstWithStackTrace = methodEvents + .stream() + .filter(event -> event.getStackTraceElementAt(startDepth) != null) //find an element which has a stack trace + .findFirst(); + if (firstWithStackTrace.isPresent()) { + StackTrace trace = firstWithStackTrace.get().getStackTrace(); + int currentDepth = startDepth; + while (currentDepth < trace.size() && !isSameMethod(trace.get(currentDepth), entryEvent)) { + currentDepth++; + } + // After the loop, currentDepth is bigger than the trace OR points at the found span + // if currentDepth is bigger than the trace, this means that no matching method has been found + // This can happen because the timings of stack trace samples are inaccurate, leading to samples "sliding" in + // ATM, we just accept this and use the invalid stack trace as parent, leading to potential inaccuracies + // In the future, we should remove such "invalid" samples from the list of events to prevent this. + StackTrace cutTrace = trace.createSubTrace(currentDepth); + MethodEntryEvent newEntry = entryEvent.copyWithNewStackTrace(cutTrace); + MethodExitEvent newExit = new MethodExitEvent(newEntry, exitEvent.getTimestamp()); + + output.add(newEntry); + assignStackTracesToMethodEntries(methodEvents.subList(1, methodEvents.size() - 1), durations, currentDepth + 1, output); + output.add(newExit); //add the new end-event + } else { + //no stack trace occured between method start and end, keep the events as-is + output.addAll(methodEvents); + } + offset += duration + 1; //point after the exit event! + } else if (origEvent instanceof MethodExitEvent) { + throw new IllegalStateException("This case should never happen!"); + } else { + output.add(origEvent); //keep unchanged + offset++; + } + } + } + + private static boolean isSameMethod(StackTraceElement stackTraceElement, MethodEntryEvent entryEvent) { + return entryEvent.getClassName().equals(stackTraceElement.getClassName()) + && entryEvent.getMethodName().equals(stackTraceElement.getMethodName()); + } + + /** + * Computes the duration of every observed instrumented method call. + * Duration hereby does NOT mean time! Instead the number of events from start to end is counted. + * E.g. given an entry event at index i in the event list, its corresponding exit event will be found at the index i+duration. + * + * @param events the list of events in the order they appeared. + * + * @return the duration map + */ + private static Map getMethodDurations(List events) { + Map entryIndex = new HashMap<>(); + Map durations = new HashMap<>(); + for (int i = 0; i < events.size(); i++) { + TraceEvent event = events.get(i); + if (event instanceof MethodEntryEvent) { + entryIndex.put((MethodEntryEvent) event, i); + } else if (event instanceof MethodExitEvent) { + MethodEntryEvent entryEvent = ((MethodExitEvent) event).getEntryEvent(); + int startIndex = entryIndex.get(entryEvent); + durations.put(entryEvent, i - startIndex); + } + } + return durations; + } + + /** + * Given an Invocation which is known to be at stack-trace depth x, + * this method will try to find all its child invocations (method calls at depth x+1). + *

+ * In order to do so, this method needs the list of events which have occurred within the duration of this parent Invocation. + * + * @param events the list of events which have occurred during the execution of the parent invocation + * @param depth the depth at which we scan for the child invocation. This implies that the parent invocation is located at (depth-1). + * @param parent the parent invocation to which the found child-invocations will be added as children. + */ + private static void resolveChildInvocations(List events, int depth, Invocation parent) { + //walk the events left-to-right to identify the calls + int offset = 0; + while (offset < events.size()) { + TraceEvent current = events.get(offset); + if (current.getStackTraceElementAt(depth) != null) { + int endIndex = findLastEqualEvent(events, offset, depth); + endIndex = extendEndToIncludeInstrumentations(events, offset, endIndex); + if (offset != endIndex) { //at least two events have fallen into the range + resolveSampledInvocation(events.subList(offset, endIndex + 1), depth, parent); + } + offset = endIndex + 1; //continue with all unprocessed events + } else if (current instanceof MethodEntryEvent) { + int endIndex = findMethodExitEvent(events, offset); + resolveInstrumentedInvocation(events.subList(offset, endIndex + 1), depth, parent); + offset = endIndex + 1; //continue with the next child + } else { + offset++; + } + } + } + + /** + * Walks the list of events in time, searching for the first event which does not have the same method at the given stack trace depth. + * As soon as such an event is encountered, the index of the last matching event is returned. + * + * @param events the list of events to scan + * @param compareIndex we search for the last element relative to this index which is equal to events[compareIndex] + * @param depth the depth at which operate within the stack traces + * + * @return the index of the last matching event (which is potentially equal to compareIndex). + */ + private static int findLastEqualEvent(List events, int compareIndex, int depth) { + TraceEvent compareTo = events.get(compareIndex); + StackTraceElement cmpParent = compareTo.getStackTraceElementAt(depth - 1); + StackTraceElement cmpElement = compareTo.getStackTraceElementAt(depth); + int lastMatchingIndex = compareIndex; + for (int i = compareIndex + 1; i < events.size(); i++) { + TraceEvent other = events.get(i); + if (other.getStackTrace() != null) { //ignore events without stacktraces + StackTraceElement parent = other.getStackTraceElementAt(depth - 1); + StackTraceElement element = other.getStackTraceElementAt(depth); + if (element == null) { //stack trace is not deep enough + return lastMatchingIndex; + } + if (!stackTraceElementsEqual(cmpElement, cmpParent, element, parent)) { + return lastMatchingIndex; + } else { + lastMatchingIndex = i; + } + } + } + return lastMatchingIndex; // all are equal + } + + /** + * Given a list of events and a range [startIndex,endIndex] within it. + * This method extends endIndex, in case method calls where started within this range and not finished. + * This ensures that no method calls are started but not finsihed within the range [startIndex,resultIndex]. + * + * @param events the list to scan + * @param startIndex the start of the range to (potentially) extend (inclusive) + * @param endIndex the end of the range to (potentially) extend (inclusive) + * + * @return an index x greater or equal to endIndex, so that the within the range [startIndex, x] no method calls are started but not ended + */ + private static int extendEndToIncludeInstrumentations(List events, int startIndex, int endIndex) { + int entryCount = 0; + int newEnd = startIndex - 1; + while (newEnd < endIndex || entryCount != 0) { + newEnd++; + if (events.get(newEnd) instanceof MethodEntryEvent) { + entryCount++; + } else if (events.get(newEnd) instanceof MethodExitEvent) { + entryCount--; + } + } + return newEnd; + } + + private static boolean stackTraceElementsEqual(StackTraceElement first, StackTraceElement parentOfFirst, StackTraceElement second, StackTraceElement parentOfSecond) { + if (!Objects.equals(first.getMethodName(), second.getMethodName())) { + return false; + } + if (!Objects.equals(first.getClassName(), second.getClassName())) { + return false; + } + if (!Objects.equals(parentOfFirst.getFileName(), parentOfSecond.getFileName())) { + return false; + } + if (parentOfFirst.getLineNumber() != parentOfSecond.getLineNumber()) { + return false; + } + return true; + } + + private static int findMethodExitEvent(List events, int methodEntryIndex) { + MethodEntryEvent entry = (MethodEntryEvent) events.get(methodEntryIndex); + for (int i = methodEntryIndex + 1; i < events.size(); i++) { + if (events.get(i) instanceof MethodExitEvent) { + MethodExitEvent exit = (MethodExitEvent) events.get(i); + if (exit.getEntryEvent() == entry) { + return i; + } + } + } + throw new IllegalArgumentException("Could not find a matching Exit-Event!"); + } + + private static void resolveInstrumentedInvocation(List events, int depth, Invocation parent) { + MethodEntryEvent start = (MethodEntryEvent) events.get(0); + MethodExitEvent end = (MethodExitEvent) events.get(events.size() - 1); + + Invocation instrumentedMethod = new Invocation(start, end, start.getPlaceholderSpan(), start.getContinuedSpan()); + parent.addChild(instrumentedMethod); + + List eventsWithoutStartAndEnd = events.subList(1, events.size() - 1); + resolveChildInvocations(eventsWithoutStartAndEnd, depth + 1, instrumentedMethod); + } + + private static void resolveSampledInvocation(List events, int depth, Invocation parent) { + TraceEvent startEvent = events.get(0); + TraceEvent endEvent = events.get(events.size() - 1); + + StackTraceElement element = startEvent.getStackTrace().get(depth); + Invocation sampledMethod = new Invocation(startEvent, endEvent, element); + parent.addChild(sampledMethod); + + resolveChildInvocations(events, depth + 1, sampledMethod); + } + +} diff --git a/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/PlaceholderSpan.java b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/PlaceholderSpan.java new file mode 100644 index 0000000000..73cde30633 --- /dev/null +++ b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/PlaceholderSpan.java @@ -0,0 +1,128 @@ +package rocks.inspectit.ocelot.core.instrumentation.autotracing; + +import io.opencensus.implcore.internal.TimestampConverter; +import io.opencensus.trace.*; + +import java.util.EnumSet; +import java.util.HashMap; +import java.util.Map; +import java.util.Random; +import java.util.function.Supplier; + +/** + * A {@link Span}, which acts as a placeholder. + * This span can be actiavated via {@link Tracer#withSpan(Span)} normally and act as a parent of other spans. + *

+ * However, when {@link #end(EndSpanOptions)} is called, the span is not exported immidately. + * Instead it will only be exported after both {@link #end(EndSpanOptions)} and {@link #exportWithParent(Span, TimestampConverter)} have been called. + */ +public class PlaceholderSpan extends Span { + + /** + * Used for generating a span-ids + */ + private static final Random RANDOM = new Random(); + + /** + * Stores the attributes added to this span. + */ + private Map attributes = new HashMap<>(); + + private String spanName; + + private Span.Kind spanKind; + + private Supplier clock; + + private long startTime; + + private long endTime = 0L; + + private Span newParent; + + private boolean exported = false; + + private TimestampConverter converter; + + PlaceholderSpan(SpanContext defaultParent, String spanName, Span.Kind kind, Supplier clock) { + super(generateContext(defaultParent), EnumSet.of(Span.Options.RECORD_EVENTS)); + this.spanName = spanName; + spanKind = kind; + this.clock = clock; + startTime = clock.get(); + } + + private static SpanContext generateContext(SpanContext parentContext) { + SpanId id = SpanId.generateRandomId(RANDOM); + return SpanContext.create(parentContext.getTraceId(), id, parentContext.getTraceOptions(), parentContext + .getTracestate()); + } + + @Override + public void putAttribute(String key, AttributeValue value) { + attributes.put(key, value); + } + + @Override + public void putAttributes(Map attributes) { + this.attributes.putAll(attributes); + } + + @Override + public void addAnnotation(String description, Map attributes) { + //not supported yet + } + + @Override + public void addAnnotation(Annotation annotation) { + //not supported yet + } + + @Override + public void addLink(Link link) { + //not supported yet + } + + @Override + public synchronized void end(EndSpanOptions options) { + endTime = clock.get(); + if (newParent != null) { + export(); + } + } + + /** + * Alters the parent of this span. May only be called exactly once. + * + * @param newParent the parent to use + * @param converter the timestamp converter to use + */ + public synchronized void exportWithParent(Span newParent, TimestampConverter converter) { + this.converter = converter; + this.newParent = newParent; + if (endTime != 0) { + export(); + } + } + + private void export() { + if (!exported) { + exported = true; + Span span = CustomSpanBuilder.builder(spanName, newParent) + .kind(spanKind) + .customTiming(startTime, endTime, converter) + .spanId(getContext().getSpanId()) + .startSpan(); + span.putAttributes(attributes); + span.end(); + } + } + + public long getStartTime() { + return startTime; + } + + public String getSpanName() { + return spanName; + } +} diff --git a/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/SampledTrace.java b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/SampledTrace.java new file mode 100644 index 0000000000..aefe99322a --- /dev/null +++ b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/SampledTrace.java @@ -0,0 +1,248 @@ +package rocks.inspectit.ocelot.core.instrumentation.autotracing; + +import com.google.common.annotations.VisibleForTesting; +import io.opencensus.implcore.internal.TimestampConverter; +import io.opencensus.implcore.trace.RecordEventsSpanImpl; +import io.opencensus.trace.AttributeValue; +import io.opencensus.trace.Span; +import rocks.inspectit.ocelot.core.instrumentation.autotracing.events.MethodEntryEvent; +import rocks.inspectit.ocelot.core.instrumentation.autotracing.events.MethodExitEvent; +import rocks.inspectit.ocelot.core.instrumentation.autotracing.events.StackTraceSampledEvent; +import rocks.inspectit.ocelot.core.instrumentation.autotracing.events.TraceEvent; + +import java.util.ArrayList; +import java.util.Collections; +import java.util.List; +import java.util.function.Supplier; +import java.util.stream.Collectors; + +/** + * This is the data structure which holds all recorded information to reconstruct a trace based on both instrumented methods + * as well as collected stack trace samples. + * Namely, this information is simply a list of events. + *

+ * The actual algorithm for this reconstruction is defined by the {@link InvocationResolver}. + */ +public class SampledTrace { + + /** + * Function to mark a method invocation started via {@link #newSpanStarted(PlaceholderSpan, String, String)} + * or {@link #spanContinued(Span, long, String, String)} as finished. + */ + public interface MethodExitNotifier { + + void methodFinished(long timestamp); + } + + /** + * Flag, whether this trace is finished. + * If it is finished, no more events will be recorded (they will be ignored). + */ + private volatile boolean isFinished; + + /** + * A flag indicating whether the sample recording is paused. + * This flag is not directly used in this class, it should instead be read and respected + * by the entity which also calls {@link #addStackTrace(StackTrace, long).} + */ + private volatile boolean isPaused; + + /** + * In order to reconstruct the stack trace, we need to know how many frames on the stack trace should be ignored. + * For this purpose we need a stack trace of the method which started the stack-trace sampling. + * We capture the stack-trace by creating a new Throwable instance (the constructor captures the stack trace). + * While capturing the stack-trace is expensive, it is even more expensive to load it from the JVM-native structure into java + * via {@link Throwable#getStackTrace()}. For this reason we "Delay" the loading until it is actually needed. + */ + private Supplier rootStackTraceProvider; + + /** + * The span which acts as a root for all sampled methods. + */ + private Span rootSpan; + + /** + * The list storing the sequence of events. + * E.g. whenever a stack-trace sample is recorded or an instrumented method is entered or exited, + * a corresponding event is appended to this list. + *

+ * This means that the order of the events in this List corresponds to the order in time in which the events occurred! + */ + private ArrayList events; + + public SampledTrace(Span rootSpan, Supplier rootStackTraceProvider) { + this.rootStackTraceProvider = rootStackTraceProvider; + this.rootSpan = rootSpan; + events = new ArrayList<>(); + isFinished = false; + isPaused = false; + } + + /** + * Marks this trace as finished, meaning that no future data will be recorded. + */ + public synchronized void finish() { + isFinished = true; + } + + /** + * Checks if the sampling is currently configured to be paused. + * + * @return true, if it is paused + */ + public boolean isPaused() { + return isPaused; + } + + /** + * Changes the pause-state. + * + * @param paused true, if sampling should be configured to be paused + */ + public void setPaused(boolean paused) { + isPaused = paused; + } + + /** + * Called when a new stack trace has been recorded. + * + * @param stackTrace the new stack trace + * @param timestamp the (approximate) timestamp when the stack trace was recorded + */ + public synchronized void addStackTrace(StackTrace stackTrace, long timestamp) { + if (!isFinished) { + events.add(new StackTraceSampledEvent(stackTrace, timestamp)); + } + } + + /** + * Should be called when an instrumented method is called within this trace. + * This ensures that the method is correctly placed between the sampled method calls. + * + * @param span the placeholder for the newly started method + * @param className the class declaring the method which was invoked (used to locate it within stack traces) + * @param methodName the name of the method which has been invoked (used to locate it within stack traces) + * + * @return a callback which must be invoked as soon as the method finishes. + */ + public synchronized MethodExitNotifier newSpanStarted(PlaceholderSpan span, String className, String methodName) { + if (!isFinished) { + MethodEntryEvent entryEvent = new MethodEntryEvent(span, null, span.getStartTime(), className, methodName, null); + events.add(entryEvent); + return (exitTime) -> addExit(entryEvent, exitTime); + } + return (time) -> { + }; //Return NOOP if already finished + } + + /** + * Should be called when an instrumented method is called within this trace, which however does continue an exisitign span instead of creating a new one. + * This ensures that the method is correctly placed between the sampled method calls. + * + * @param span the span which was continued + * @param startTime the entry timestamp of the method call + * @param className the class declaring the method which was invoked (used to locate it within stack traces) + * @param methodName the name of the method which has been invoked (used to locate it within stack traces) + * + * @return a callback which must be invoked as soon as the method finishes. + */ + public synchronized MethodExitNotifier spanContinued(Span span, long startTime, String className, String methodName) { + if (!isFinished) { + MethodEntryEvent entryEvent = new MethodEntryEvent(null, span, startTime, className, methodName, null); + events.add(entryEvent); + return (exitTime) -> addExit(entryEvent, exitTime); + } + return (time) -> { + }; //Return NOOP if already finished + } + + private synchronized void addExit(MethodEntryEvent entryEvent, long timestamp) { + if (!isFinished) { + events.add(new MethodExitEvent(entryEvent, timestamp)); + } + } + + /** + * Reconstructs the trace from the series of stack trace samples and method entry / exit events. + * The reconstructed trace is exported via open-census. + */ + public void export() { + Iterable invocations = generateInvocations(); + for (Invocation invoc : invocations) { + exportWithChildren(invoc, rootSpan); + } + } + + /** + * Converts the list of events to a tree of {@link Invocation}s. + * + * @return + */ + @VisibleForTesting + Iterable generateInvocations() { + StackTrace rootTrace = rootStackTraceProvider.get(); + int rootDepth = rootTrace.size() - 1; + Iterable invocations = InvocationResolver.convertEventsToInvocations(events, rootDepth); + return invocations; + } + + private void exportWithChildren(Invocation invoc, Span parentSpan) { + Span span; + if (invoc.getSampledMethod() == null) { + if (invoc.getPlaceholderSpan() != null) { + span = invoc.getPlaceholderSpan(); + addHiddenParentsAttribute(span, invoc); + invoc.getPlaceholderSpan().exportWithParent(parentSpan, getTimestampConverter()); + } else { + span = invoc.getContinuedSpan(); + } + } else { + if (!invoc.isHidden()) { + span = CustomSpanBuilder.builder("*" + getSimpleName(invoc.getSampledMethod()), parentSpan) + .customTiming(invoc.getStart().getTimestamp(), invoc.getEnd() + .getTimestamp(), getTimestampConverter()) + .startSpan(); + span.putAttribute("java.sampled", AttributeValue.booleanAttributeValue(true)); + span.putAttribute("java.fqn", AttributeValue.stringAttributeValue(getFullName(invoc.getSampledMethod()))); + addHiddenParentsAttribute(span, invoc); + span.end(); + } else { + span = parentSpan; + } + } + for (Invocation child : invoc.getChildren()) { + exportWithChildren(child, span); + } + } + + private void addHiddenParentsAttribute(Span span, Invocation invoc) { + List hiddenParents = new ArrayList<>(); + Invocation parent = invoc.getParent(); + while (parent != null && parent.isHidden()) { + hiddenParents.add(parent); + parent = parent.getParent(); + } + if (hiddenParents.size() > 0) { + Collections.reverse(hiddenParents); + String parents = hiddenParents.stream() + .map(inv -> inv.getSampledMethod().toString()) + .collect(Collectors.joining("\n")); + span.putAttribute("java.hidden_parents", AttributeValue.stringAttributeValue(parents)); + } + } + + private TimestampConverter getTimestampConverter() { + return CustomSpanBuilder.getTimestampConverter((RecordEventsSpanImpl) rootSpan); + } + + private String getSimpleName(StackTraceElement element) { + String className = element.getClassName(); + return className.substring(className.lastIndexOf('.') + 1) + "." + element.getMethodName(); + } + + private String getFullName(StackTraceElement element) { + String className = element.getClassName(); + return className + "." + element.getMethodName(); + } + +} diff --git a/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/StackTrace.java b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/StackTrace.java new file mode 100644 index 0000000000..7a99b36d24 --- /dev/null +++ b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/StackTrace.java @@ -0,0 +1,136 @@ +package rocks.inspectit.ocelot.core.instrumentation.autotracing; + +import com.google.common.annotations.VisibleForTesting; + +import java.lang.management.ManagementFactory; +import java.lang.management.ThreadInfo; +import java.lang.management.ThreadMXBean; +import java.util.Collection; +import java.util.HashMap; +import java.util.Map; +import java.util.stream.Collectors; + +/** + * A wrapper for an Array of {@link StackTraceElement}s as returned by {@link Thread#getStackTrace}. + * This wrapper performs a cleanup removing the following stack frames: + * - All top stackframes containining inspectit-code or Thread.getStackTrace + * - All stack frames which are in Lambda-code + *

+ * Lambda-stackframes are removed due to an inconsistency between calling {@link Thread#getStackTrace} for the own vs another thread. + * When calling it from the own Thread, Lambda expressions are often omitted by the JVM. + * For this reason we remove them in general to avoid inconsistencies. + */ +public class StackTrace { + + public static final int MAX_DEPTH = 8096; + + private StackTraceElement[] data; + + private static final ThreadMXBean THREAD_BEAN = ManagementFactory.getThreadMXBean(); + + private int size; + + @VisibleForTesting + StackTrace(StackTraceElement[] stackTrace) { + data = stackTrace; + size = stackTrace.length; + cleanup(); + } + + private StackTrace(StackTraceElement[] data, int size) { + this.data = data; + this.size = size; + } + + /** + * Creates a stack trace based on the stack trace of a given throwable. + * + * @param stackTraceHolder the throwable containing the stack trace. + * + * @return a stack trace constructed from the given throwable. + */ + public static StackTrace createFromThrowable(Throwable stackTraceHolder) { + return new StackTrace(stackTraceHolder.getStackTrace()); + } + + /** + * Returns a stacktrace for each of the specified Threads. + * When more than one thread is requested, {@link Thread#getAllStackTraces()} will be used. + * The reason is that this way only one safepoint needs to be reached instead of N (where N is the number of Threads) + * + * @param threads + * + * @return + */ + public static Map createFor(Collection threads) { + long[] ids = threads.stream().mapToLong(Thread::getId).toArray(); + Map idsToThreads = threads.stream() + .collect(Collectors.toMap(Thread::getId, thread -> thread)); + + ThreadInfo[] threadInfos = THREAD_BEAN.getThreadInfo(ids, MAX_DEPTH); + + Map result = new HashMap<>(); + + for (int i = 0; i < threadInfos.length; i++) { + Thread thread = idsToThreads.get(ids[i]); + StackTraceElement[] stackTrace = threadInfos[i].getStackTrace(); + if (stackTrace != null && stackTrace.length > 0) { + result.put(thread, new StackTrace(stackTrace)); + } + } + return result; + } + + private void cleanup() { + while (isHiddenTop(getStackTop())) { + removeStackTop(); + } + int deletedCount = 0; + for (int i = data.length - 1; i >= data.length - size; i--) { + if (isLambda(data[i])) { + deletedCount++; + } else { + data[i + deletedCount] = data[i]; + } + } + size -= deletedCount; + } + + private boolean isHiddenTop(StackTraceElement element) { + return element.getClassName().startsWith("rocks.inspectit.ocelot.core.") + || element.getClassName().startsWith("rocks.inspectit.ocelot.bootstrap.") + || isLambda(element); + } + + private boolean isLambda(StackTraceElement element) { + String className = element.getClassName(); + return className.contains("$Lambda$"); + } + + public StackTraceElement get(int indexFromRoot) { + return data[data.length - 1 - indexFromRoot]; + } + + public StackTraceElement getStackTop() { + return get(size - 1); + } + + public void removeStackTop() { + size--; + } + + public int size() { + return size; + } + + /** + * Creates a stack trace from this trace by returning the elements from the root up to the given depth. + * + * @param size the depth of the sub-stack trace t oreturn. + * + * @return the new stack trace + */ + public StackTrace createSubTrace(int size) { + return new StackTrace(data, size); + } +} diff --git a/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/StackTraceSampler.java b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/StackTraceSampler.java new file mode 100644 index 0000000000..49c5dc157c --- /dev/null +++ b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/StackTraceSampler.java @@ -0,0 +1,316 @@ +package rocks.inspectit.ocelot.core.instrumentation.autotracing; + +import io.opencensus.common.Clock; +import io.opencensus.common.Scope; +import io.opencensus.trace.*; +import lombok.extern.slf4j.Slf4j; +import org.springframework.beans.factory.annotation.Autowired; +import org.springframework.context.event.EventListener; +import org.springframework.stereotype.Component; +import rocks.inspectit.ocelot.config.model.tracing.AutoTracingSettings; +import rocks.inspectit.ocelot.core.config.InspectitConfigChangedEvent; +import rocks.inspectit.ocelot.core.config.InspectitEnvironment; +import rocks.inspectit.ocelot.core.instrumentation.hook.MethodReflectionInformation; +import rocks.inspectit.ocelot.core.utils.HighPrecisionTimer; + +import javax.annotation.PostConstruct; +import javax.annotation.PreDestroy; +import java.util.HashMap; +import java.util.Map; +import java.util.Set; +import java.util.concurrent.*; +import java.util.stream.Collectors; + +/** + * Component for executing stack-trace-sampling (=auto-tracing). + */ +@Component +@Slf4j +public class StackTraceSampler { + + /** + * Stack-trace samples require a post-processing before being exported as traces. + * This happens asynchronously to the application to minimize the performance impact in a periodicalyl executed task. + * This value defines the frequency at which the queue is checked. + */ + public static final int EXPORT_INTERVAL_MILLIS = 200; + + /** + * The change to apply to the state of the sampler when invoking {@link #createAndEnterSpan(String, SpanContext, Sampler, Span.Kind, MethodReflectionInformation, Mode)} + * or {@link #continueSpan(Span, MethodReflectionInformation, Mode)}. + */ + public enum Mode { + /** + * Starts stack-trace sampling if it is not already active. + */ + ENABLE, + /** + * Pauses the stack-trace sampling if it was activated by a parent call. + */ + DISABLE, + /** + * Preserves the state of the stack trace sampling for the current thread. + */ + KEEP + } + + @Autowired + private InspectitEnvironment env; + + @Autowired + private ScheduledExecutorService executor; + + /** + * The task periodicalyl executed for ptocessing the {@link #tracesToExport} queue. + */ + private Future exportTask; + + /** + * A bounded queue containing all traces which have finished but need to be processed for exporting. + */ + private ArrayBlockingQueue tracesToExport = new ArrayBlockingQueue<>(4096); + + /** + * Global map which stores all threads for which stack-trace sampling is currently active. + * If a thread is present in this map, it will be sampled and the stack trace will be added to the corresponding trace. + */ + private ConcurrentHashMap activeSamplings = new ConcurrentHashMap<>(); + + /** + * The timer used to trigger the capturing of stack-trace samples. + */ + private HighPrecisionTimer sampleTimer; + + /** + * The clock used for timing the stack-traces. + * This clock must be the same as used for OpenCensus {@link Span}s, to make sure that the timings are consistent. + */ + private Clock clock = Tracing.getClock(); + + @PostConstruct + void init() { + exportTask = executor.scheduleWithFixedDelay(this::doExportTraces, EXPORT_INTERVAL_MILLIS, EXPORT_INTERVAL_MILLIS, TimeUnit.MILLISECONDS); + AutoTracingSettings settings = env.getCurrentConfig().getTracing().getAutoTracing(); + sampleTimer = new HighPrecisionTimer("Ocelot stack trace sampler", settings.getFrequency(), + settings.getShutdownDelay(), this::doSample); + } + + @EventListener(InspectitConfigChangedEvent.class) + void updateTimer() { + AutoTracingSettings settings = env.getCurrentConfig().getTracing().getAutoTracing(); + sampleTimer.setPeriod(settings.getFrequency()); + sampleTimer.setMaximumInactivity(settings.getShutdownDelay()); + } + + @PreDestroy + void shutdown() { + exportTask.cancel(false); + sampleTimer.destroy(); + } + + /** + * Starts a new span with the given details. + *

+ * If mode is ENABLE and stack trace sampling is not active for the current, + * this span will generate its children using stack trace sampling. + * If mode is ENABLE and a parent span already started stack trace sampling, + * the sampler will attempt to correctly place this span between the stack-trace sample generated ones. + *

+ * If mode is DISABLE and a stack-trace sampling session exists on the current thread, it will be paused. + * The mode KEEP will simply preserver the current sampling status. + * + * @param name the name of the span to create + * @param remoteParent the (optional) remote parent of the span, should only be set if this span is a root. + * @param sampler the sampler to use (not for stack-trace sampling but for span sampling) + * @param kind the (optional) kind of the span + * @param actualMethod the actual method for which this span is created. + * @param mode the mode to use for Stack-Trace sampling. + * + * @return The generated span is activated via {@link Tracer#withSpan(Span)}. The resulting context is wrapped with a context which terminates the stack-trace-sampling. + */ + public AutoCloseable createAndEnterSpan(String name, SpanContext remoteParent, Sampler sampler, Span.Kind kind, MethodReflectionInformation actualMethod, Mode mode) { + Thread self = Thread.currentThread(); + SampledTrace activeSampling = activeSamplings.get(self); + if (activeSampling == null) { + if (mode == Mode.ENABLE) { + return startSampling(name, remoteParent, sampler, kind); + } else { + return Tracing.getTracer().withSpan(createNormalSpan(name, remoteParent, sampler, kind)); + } + } else { + AutoCloseable samplingAwareSpanContext = createSamplingAwareSpan(name, remoteParent, kind, actualMethod, activeSampling); + return createPauseAdjustingContext(mode, activeSampling, samplingAwareSpanContext); + } + } + + /** + * Continues a span but makes it's children stack-trace sampling aware. + *

+ * If mode is ENABLE and stack trace sampling is not active for the current, + * this span will generate its children using stack trace sampling. + * If mode is ENABLE and a parent span already started stack trace sampling, + * the sampler will attempt to correctly place this span between the stack-trace sample generated ones. + *

+ * If mode is DISABLE and a stack-trace sampling session exists on the current thread, it will be paused. + * The mode KEEP will simply preserver the current sampling status. + * + * @param span the span to continue + * @param actualMethod the actual method for which this span is made active + * @param mode the mode to use for stack trace sampling. + * + * @return The span is activated via {@link Tracer#withSpan(Span)}. The resulting context is wrapped with a context which terminates the stack-trace-sampling. + */ + public AutoCloseable continueSpan(Span span, MethodReflectionInformation actualMethod, Mode mode) { + Thread self = Thread.currentThread(); + SampledTrace activeSampling = activeSamplings.get(self); + if (activeSampling == null) { + if (mode == Mode.ENABLE) { + return startSampling(span); + } else { + return Tracing.getTracer().withSpan(span); + } + } else { + AutoCloseable samplingAwareSpanContext = continueSamplingAwareSpan(span, actualMethod, activeSampling); + return createPauseAdjustingContext(mode, activeSampling, samplingAwareSpanContext); + } + } + + /** + * Wraps the given spanContext in order to pause the stack-trace sampling if required. + * + * @param mode the mode (used to check whether altering the pause-state is required). + * @param activeSampling the currently active sampling session + * @param spanContext the span-context to wrap + * + * @return the wrapped span-context which alters the pause state accordingly. + */ + private AutoCloseable createPauseAdjustingContext(Mode mode, SampledTrace activeSampling, AutoCloseable spanContext) { + if (activeSampling.isPaused() && mode == Mode.ENABLE) { + activeSampling.setPaused(false); + return () -> { + spanContext.close(); + activeSampling.setPaused(true); + }; + } else if (!activeSampling.isPaused() && mode == Mode.DISABLE) { + activeSampling.setPaused(true); + return () -> { + spanContext.close(); + activeSampling.setPaused(false); + }; + } else { + return spanContext; + } + } + + private AutoCloseable continueSamplingAwareSpan(Span spanToContinue, MethodReflectionInformation actualMethod, SampledTrace activeSampling) { + SampledTrace.MethodExitNotifier exitCallback = activeSampling + .spanContinued(spanToContinue, clock.nowNanos(), actualMethod.getDeclaringClass() + .getName(), actualMethod.getName()); + Scope ctx = Tracing.getTracer().withSpan(spanToContinue); + return () -> { + ctx.close(); + exitCallback.methodFinished(clock.nowNanos()); + }; + } + + private AutoCloseable startSampling(String name, SpanContext remoteParent, Sampler sampler, Span.Kind kind) { + Span rootSpan = createNormalSpan(name, remoteParent, sampler, kind); + return startSampling(rootSpan); + } + + private AutoCloseable startSampling(Span rootSpan) { + boolean spanExists = rootSpan.getContext().isValid() && rootSpan.getContext().getTraceOptions().isSampled(); + if (!spanExists) { + return Tracing.getTracer().withSpan(rootSpan); + } else { + Throwable stackTrace = new Throwable(); //the constructor collects the current stack-trace + SampledTrace sampledTrace = new SampledTrace(rootSpan, () -> StackTrace.createFromThrowable(stackTrace)); + Thread selfThread = Thread.currentThread(); + activeSamplings.put(selfThread, sampledTrace); + sampleTimer.start(); + AutoCloseable spanScope = Tracing.getTracer().withSpan(rootSpan); + return () -> { + spanScope.close(); + activeSamplings.remove(selfThread); + sampledTrace.finish(); + addToExportQueue(sampledTrace); + }; + } + } + + private AutoCloseable createSamplingAwareSpan(String name, SpanContext remoteParent, Span.Kind kind, MethodReflectionInformation actualMethod, SampledTrace activeSampling) { + SpanContext parent = remoteParent; + if (remoteParent == null) { + parent = Tracing.getTracer().getCurrentSpan().getContext(); + } + PlaceholderSpan span = new PlaceholderSpan(parent, name, kind, clock::nowNanos); + SampledTrace.MethodExitNotifier exitCallback = activeSampling + .newSpanStarted(span, actualMethod.getDeclaringClass().getName(), actualMethod.getName()); + Scope ctx = Tracing.getTracer().withSpan(span); + return () -> { + ctx.close(); + exitCallback.methodFinished(clock.nowNanos()); + }; + } + + private Span createNormalSpan(String name, SpanContext remoteParent, Sampler sampler, Span.Kind kind) { + SpanBuilder builder; + if (remoteParent != null) { + builder = Tracing.getTracer().spanBuilderWithRemoteParent(name, remoteParent); + } else { + builder = Tracing.getTracer().spanBuilder(name); + } + builder.setSpanKind(kind); + if (sampler != null) { + builder.setSampler(sampler); + } + Span span = builder.startSpan(); + return span; + } + + /** + * Method invoked by a timer to sample all threads for which stack trace sampling is activated. + * Returns true, if any sampling was performed + */ + private boolean doSample() { + //copy the map to avoid concurrent modifications due to the starting and ending of sampling traces + Map samplingsCopy = new HashMap<>(activeSamplings); + + Set threadsToSample = samplingsCopy.keySet().stream() + .filter(trace -> !samplingsCopy.get(trace).isPaused()) + .collect(Collectors.toSet()); + + long timestamp = clock.nowNanos(); + Map stackTraces = StackTrace.createFor(threadsToSample); + + boolean anySampled = false; + + for (Thread thread : threadsToSample) { + SampledTrace trace = samplingsCopy.get(thread); + StackTrace stackTrace = stackTraces.get(thread); + if (stackTrace != null) { //recheck for concurrent finishSampling() calls + anySampled = true; + trace.addStackTrace(stackTrace, timestamp); //has no effect if the trace was finished concurrently + } + } + + return anySampled; + } + + private void addToExportQueue(SampledTrace sampledTrace) { + if (!tracesToExport.offer(sampledTrace)) { + log.warn("Dropping sampled-spans! Please reduce your auto-tracing scope!"); + } + } + + private void doExportTraces() { + while (!tracesToExport.isEmpty()) { + try { + tracesToExport.poll().export(); + } catch (Exception e) { + log.error("Error exporting sampled trace", e); + } + } + } + +} diff --git a/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/events/MethodEntryEvent.java b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/events/MethodEntryEvent.java new file mode 100644 index 0000000000..b5cdbe494b --- /dev/null +++ b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/events/MethodEntryEvent.java @@ -0,0 +1,71 @@ +package rocks.inspectit.ocelot.core.instrumentation.autotracing.events; + +import io.opencensus.trace.Span; +import lombok.Value; +import rocks.inspectit.ocelot.core.instrumentation.autotracing.PlaceholderSpan; +import rocks.inspectit.ocelot.core.instrumentation.autotracing.StackTrace; + +/** + * This event represents the start of an instrumented and traced method. + * If a method is traced normally within a trace with stack trace sampling enabled, + * special handling is required. The parent span of the method might need to be changed when the stack-trace samples are analyzed. + *

+ * For this reason, no normal span is created for such methods, instead a {@link PlaceholderSpan} is used which never actually gets exported. + * A placeholder-span however does reserve a span-id (so for example trace-id-propagation works correctly). + *

+ * Every {@link MethodEntryEvent} also has a {@link MethodExitEvent} which together define the duration of the method call. + */ +@Value +public class MethodEntryEvent implements TraceEvent { + + /** + * If this method invocation started a new span, is is stored in this variable. + * Either {@link #placeholderSpan} or {@link #continuedSpan} are not null. + */ + private PlaceholderSpan placeholderSpan; + + /** + * If this method continued an existing span, the continued span is stored in this variable. + * Either {@link #placeholderSpan} or {@link #continuedSpan} are not null. + */ + private Span continuedSpan; + + /** + * The time at which the method was entered. + */ + private long timestamp; + + /** + * The fulyl qualified name of the class declaring the method which was entered. + */ + private String className; + + /** + * The name of the method which was entered. + */ + private String methodName; + + /** + * A stack trace of all parent calls. + * Does NOT include the method represented by the dummy span (=this invocation). + * Instead, the last element on the stack trace is the parent of this call. + *

+ * When recording this event this stackTrace is null for performance reasons: + * Taking an additional stack trace for each method is way to expensive. + * Instead the {@link rocks.inspectit.ocelot.core.instrumentation.autotracing.InvocationResolver} + * will attempt to create this stackTrace based on stack-trace-samples which have fallen into this methods execution. + */ + private StackTrace stackTrace; + + /** + * Creates an exact copy of this event but replaces the stackTraces with the given one. + * + * @param stackTrace the stackTrace to use for the new event. + * + * @return the copy with the stack trace replaced. + */ + public MethodEntryEvent copyWithNewStackTrace(StackTrace stackTrace) { + return new MethodEntryEvent(placeholderSpan, continuedSpan, timestamp, className, methodName, stackTrace); + } + +} diff --git a/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/events/MethodExitEvent.java b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/events/MethodExitEvent.java new file mode 100644 index 0000000000..42f2417b0b --- /dev/null +++ b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/events/MethodExitEvent.java @@ -0,0 +1,28 @@ +package rocks.inspectit.ocelot.core.instrumentation.autotracing.events; + +import lombok.Value; +import rocks.inspectit.ocelot.core.instrumentation.autotracing.StackTrace; + +/** + * This event represents the end (=return or throw) of an instrumented and traced method. + * A {@link MethodExitEvent} belogns to exactly one {@link MethodEntryEvent}. + */ +@Value +public class MethodExitEvent implements TraceEvent { + + /** + * The entry event corresponding to this exit event. + * This pair together defines the duration of the method call. + */ + private MethodEntryEvent entryEvent; + + /** + * The timestamp of this event. + */ + private long timestamp; + + @Override + public StackTrace getStackTrace() { + return null; //exit events never have a stack trace + } +} diff --git a/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/events/StackTraceSampledEvent.java b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/events/StackTraceSampledEvent.java new file mode 100644 index 0000000000..bb4e2110d4 --- /dev/null +++ b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/events/StackTraceSampledEvent.java @@ -0,0 +1,22 @@ +package rocks.inspectit.ocelot.core.instrumentation.autotracing.events; + +import lombok.Value; +import rocks.inspectit.ocelot.core.instrumentation.autotracing.StackTrace; + +/** + * This event represents a captured stack-trace of the target thread at a given timestamp. + */ +@Value +public class StackTraceSampledEvent implements TraceEvent { + + /** + * The captured stack trace. + */ + private StackTrace stackTrace; + + /** + * The time at which the stack trace was captured. + */ + private long timestamp; + +} diff --git a/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/events/TraceEvent.java b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/events/TraceEvent.java new file mode 100644 index 0000000000..6416193744 --- /dev/null +++ b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/events/TraceEvent.java @@ -0,0 +1,40 @@ +package rocks.inspectit.ocelot.core.instrumentation.autotracing.events; + +import rocks.inspectit.ocelot.core.instrumentation.autotracing.StackTrace; + +/** + * Base interface for all events required for the reconstruction of a trace from stack-trace samples and instrumented method executions. + */ +public interface TraceEvent { + + /** + * Returns the stack trace element at the given depth counted from the root method call (e.g. Thread.run()). + *

+ * If this event does not have a stack trace ({@link #getStackTrace()} returns null) + * or the stack trace is shorter than the given depth, null is returned. + * + * @param depth the depth at which the {@link StackTraceElement} shall be queried, counted from the root method. + * + * @return the element if available, otherwise null. + */ + default StackTraceElement getStackTraceElementAt(int depth) { + StackTrace st = getStackTrace(); + if (st != null && st.size() > depth) { + return st.get(depth); + } + return null; + } + + /** + * If this event has a stack-trace associated, it is returned. + * Otherwise null. + * + * @return the stack trace or null if unavailable. + */ + StackTrace getStackTrace(); + + /** + * @return the time at which this event occured. + */ + long getTimestamp(); +} diff --git a/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/config/MethodHookConfigurationResolver.java b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/config/MethodHookConfigurationResolver.java index bd6abb3ac6..e7fd123c0a 100644 --- a/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/config/MethodHookConfigurationResolver.java +++ b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/config/MethodHookConfigurationResolver.java @@ -34,6 +34,7 @@ public class MethodHookConfigurationResolver { * * @param allSettings The global instrumentation configuration, used for the global master switches * @param matchedRules All enabled rules which have a scope which matches to this method, must contain at least one value + * * @return */ public MethodHookConfiguration buildHookConfiguration(InstrumentationConfiguration allSettings, Set matchedRules) @@ -72,8 +73,13 @@ private void resolveTracing(MethodHookConfiguration.MethodHookConfigurationBuild resolveStartSpan(tracingRules, builder); resolveEndSpan(tracingRules, builder); resolveContinueSpan(tracingRules, builder); - builder.storeSpan(getAndDetectConflicts(tracingRules, r -> r.getTracing().getStoreSpan(), s -> !StringUtils.isEmpty(s), "store span data key")); - builder.errorStatus(getAndDetectConflicts(tracingRules, r -> r.getTracing().getErrorStatus(), s -> !StringUtils.isEmpty(s), "error-status data key")); + builder.storeSpan(getAndDetectConflicts(tracingRules, r -> r.getTracing() + .getStoreSpan(), s -> !StringUtils.isEmpty(s), "store span data key")); + builder.errorStatus(getAndDetectConflicts(tracingRules, r -> r.getTracing() + .getErrorStatus(), s -> !StringUtils.isEmpty(s), "error-status data key")); + builder.autoTracing(getAndDetectConflicts(tracingRules, r -> r.getTracing() + .getAutoTracing(), Objects::nonNull, "auto tracing")); + resolveSpanAttributeWriting(tracingRules, builder); result.tracing(builder.build()); @@ -94,12 +100,15 @@ private void resolveSpanAttributeWriting(Set matchedRules, Map resultAttributes = new HashMap<>(); for (String attributeKey : writtenAttributes) { - String dataKey = getAndDetectConflicts(attributeWritingRules, r -> r.getTracing().getAttributes().get(attributeKey), + String dataKey = getAndDetectConflicts(attributeWritingRules, r -> r.getTracing() + .getAttributes() + .get(attributeKey), x -> !StringUtils.isEmpty(x), "the span attribute'" + attributeKey + "'"); resultAttributes.put(attributeKey, dataKey); } builder.attributes(resultAttributes); - builder.attributeConditions(getAndDetectConflicts(attributeWritingRules, r -> r.getTracing().getAttributeConditions(), ALWAYS_TRUE, "span attribute writing conditions")); + builder.attributeConditions(getAndDetectConflicts(attributeWritingRules, r -> r.getTracing() + .getAttributeConditions(), ALWAYS_TRUE, "span attribute writing conditions")); } } @@ -107,10 +116,12 @@ private void resolveContinueSpan(Set matchedRules, RuleTrac Set rulesContinuingSpan = matchedRules.stream() .filter(r -> r.getTracing().getContinueSpan() != null) .collect(Collectors.toSet()); - String continueSpan = getAndDetectConflicts(rulesContinuingSpan, r -> r.getTracing().getContinueSpan(), ALWAYS_TRUE, "continue-span"); + String continueSpan = getAndDetectConflicts(rulesContinuingSpan, r -> r.getTracing() + .getContinueSpan(), ALWAYS_TRUE, "continue-span"); builder.continueSpan(continueSpan); if (continueSpan != null) { - builder.continueSpanConditions(getAndDetectConflicts(rulesContinuingSpan, r -> r.getTracing().getContinueSpanConditions(), ALWAYS_TRUE, "continue span conditions")); + builder.continueSpanConditions(getAndDetectConflicts(rulesContinuingSpan, r -> r.getTracing() + .getContinueSpanConditions(), ALWAYS_TRUE, "continue span conditions")); } } @@ -118,13 +129,15 @@ private void resolveEndSpan(Set matchedRules, RuleTracingSe Set rulesDefiningEndSpan = matchedRules.stream() .filter(r -> r.getTracing().getEndSpan() != null) .collect(Collectors.toSet()); - Boolean endSpanSetting = getAndDetectConflicts(rulesDefiningEndSpan, r -> r.getTracing().getEndSpan(), Objects::nonNull, "end-span"); + Boolean endSpanSetting = getAndDetectConflicts(rulesDefiningEndSpan, r -> r.getTracing() + .getEndSpan(), Objects::nonNull, "end-span"); boolean endSpan = Optional.ofNullable(endSpanSetting).orElse(true); builder.endSpan(endSpan); if (endSpan) { builder.endSpanConditions( Optional.ofNullable( - getAndDetectConflicts(rulesDefiningEndSpan, r -> r.getTracing().getEndSpanConditions(), ALWAYS_TRUE, "end span conditions") + getAndDetectConflicts(rulesDefiningEndSpan, r -> r.getTracing() + .getEndSpanConditions(), ALWAYS_TRUE, "end span conditions") ).orElse(new ConditionalActionSettings())); } } @@ -133,19 +146,23 @@ private void resolveStartSpan(Set matchedRules, RuleTracing Set rulesDefiningStartSpan = matchedRules.stream() .filter(r -> r.getTracing().getStartSpan() != null) .collect(Collectors.toSet()); - Boolean startSpanSetting = getAndDetectConflicts(rulesDefiningStartSpan, r -> r.getTracing().getStartSpan(), ALWAYS_TRUE, "start-span"); + Boolean startSpanSetting = getAndDetectConflicts(rulesDefiningStartSpan, r -> r.getTracing() + .getStartSpan(), ALWAYS_TRUE, "start-span"); boolean startSpan = Optional.ofNullable(startSpanSetting).orElse(false); builder.startSpan(startSpan); if (startSpan) { - builder.startSpanConditions(getAndDetectConflicts(rulesDefiningStartSpan, r -> r.getTracing().getStartSpanConditions(), ALWAYS_TRUE, "start span conditions")); + builder.startSpanConditions(getAndDetectConflicts(rulesDefiningStartSpan, r -> r.getTracing() + .getStartSpanConditions(), ALWAYS_TRUE, "start span conditions")); //name, kind and sample probability can be defined by rules which do not start a span themselves - builder.name(getAndDetectConflicts(matchedRules, r -> r.getTracing().getName(), n -> !StringUtils.isEmpty(n), "the span name")); - builder.kind(getAndDetectConflicts(matchedRules, r -> r.getTracing().getKind(), Objects::nonNull, "the span kind")); - builder.sampleProbability(getAndDetectConflicts(matchedRules, r -> r.getTracing().getSampleProbability(), n -> !StringUtils.isEmpty(n), "the trace sample probability")); + builder.name(getAndDetectConflicts(matchedRules, r -> r.getTracing() + .getName(), n -> !StringUtils.isEmpty(n), "the span name")); + builder.kind(getAndDetectConflicts(matchedRules, r -> r.getTracing() + .getKind(), Objects::nonNull, "the span kind")); + builder.sampleProbability(getAndDetectConflicts(matchedRules, r -> r.getTracing() + .getSampleProbability(), n -> !StringUtils.isEmpty(n), "the trace sample probability")); } } - /** * Utility function for merging configurations from multiple rules and detecting conflicts. * This method first calls the given getter on all specified rules and filters the results using the given filter. @@ -157,7 +174,9 @@ private void resolveStartSpan(Set matchedRules, RuleTracing * @param filter the predicate to filter the results of the getters with, e.g. Objects#nonNull * @param exceptionMessage the name of the setting to print in an exception message * @param the type of the value which is being queried + * * @return null if none of the rules have a setting matching the given filter. Otherwise returns the setting found. + * * @throws ConflictingDefinitionsException thrown if a conflicting setting is detected */ private T getAndDetectConflicts(Collection rules, Function getter, Predicate filter, String exceptionMessage) @@ -198,7 +217,9 @@ private void resolveMetrics(MethodHookConfiguration.MethodHookConfigurationBuild * * @param rules the rules whose generic action calls should be merged * @param actionsGetter the getter to access the rules to process, e.g. {@link InstrumentationRule#getEntryActions()} + * * @return a map mapping the data keys to the action call which define the values + * * @throws CyclicDataDependencyException if the action calls have cyclic dependencies preventing a scheduling */ private List combineAndOrderActionCalls(Set rules, Function> actionsGetter) @@ -214,10 +235,12 @@ private List combineAndOrderActionCalls(Set commonT } - /** - * If called, the given span is marked as active on the GRPC context until {@link #close()} is called. - * Note that the span will not be ended when {@link #close()} is called, it still has to be ended manually. - * MUST BE CALLED BEFORE {@link #makeActive()}! - * Must only be called at most once per {@link InspectitContextImpl} instance! - *

- * This method also performs log-trace correlation using the {@link rocks.inspectit.ocelot.bootstrap.correlation.LogTraceCorrelator}. - * - * @param span the span to enter - */ - public void enterSpan(Span span) { - if (currentSpanScope == null) { - try { - currentSpanScope = Instances.logTraceCorrelator.startCorrelatedSpanScope(() -> Tracing.getTracer().withSpan(span)); - } catch (Throwable t) { - log.error("Error activating span", t); - } - } + public void setSpanScope(AutoCloseable spanScope) { + currentSpanScope = spanScope; } /** - * @return true, if {@link #enterSpan(Span)} was called + * @return true, if {@link #enterSpan(Span, Function)} was called */ public boolean hasEnteredSpan() { return currentSpanScope != null; diff --git a/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/hook/MethodHookGenerator.java b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/hook/MethodHookGenerator.java index 48a6f98c88..7b2ec8eb64 100644 --- a/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/hook/MethodHookGenerator.java +++ b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/hook/MethodHookGenerator.java @@ -11,6 +11,7 @@ import org.springframework.stereotype.Component; import rocks.inspectit.ocelot.config.model.instrumentation.rules.MetricRecordingSettings; import rocks.inspectit.ocelot.config.model.instrumentation.rules.RuleTracingSettings; +import rocks.inspectit.ocelot.core.instrumentation.autotracing.StackTraceSampler; import rocks.inspectit.ocelot.core.instrumentation.config.model.ActionCallConfig; import rocks.inspectit.ocelot.core.instrumentation.config.model.MethodHookConfiguration; import rocks.inspectit.ocelot.core.instrumentation.context.ContextManager; @@ -56,6 +57,9 @@ public class MethodHookGenerator { @Autowired private CommonTagsToAttributesManager commonTagsToAttributesManager; + @Autowired + private StackTraceSampler stackTraceSampler; + /** * Builds a executable method hook based on the given configuration. * @@ -118,6 +122,8 @@ private List buildTracingEntryActions(RuleTracingSettings tracing) } else { actionBuilder.continueSpanCondition(ctx -> false); } + configureAutoTracing(tracing, actionBuilder); + actionBuilder.stackTraceSampler(stackTraceSampler); val result = new ArrayList(); result.add(actionBuilder.build()); @@ -131,6 +137,18 @@ private List buildTracingEntryActions(RuleTracingSettings tracing) } } + private void configureAutoTracing(RuleTracingSettings tracing, ContinueOrStartSpanAction.ContinueOrStartSpanActionBuilder actionBuilder) { + if (tracing.getAutoTracing() != null) { + if (tracing.getAutoTracing()) { + actionBuilder.autoTrace(StackTraceSampler.Mode.ENABLE); + } else { + actionBuilder.autoTrace(StackTraceSampler.Mode.DISABLE); + } + } else { + actionBuilder.autoTrace(StackTraceSampler.Mode.KEEP); + } + } + private void configureSampling(RuleTracingSettings tracing, ContinueOrStartSpanAction.ContinueOrStartSpanActionBuilder actionBuilder) { String sampleProbability = tracing.getSampleProbability(); if (!StringUtils.isBlank(sampleProbability)) { diff --git a/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/hook/actions/span/ContinueOrStartSpanAction.java b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/hook/actions/span/ContinueOrStartSpanAction.java index 9e64b338f0..49ab2401b9 100644 --- a/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/hook/actions/span/ContinueOrStartSpanAction.java +++ b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/instrumentation/hook/actions/span/ContinueOrStartSpanAction.java @@ -5,8 +5,11 @@ import io.opencensus.trace.samplers.Samplers; import lombok.AllArgsConstructor; import lombok.Builder; +import lombok.extern.slf4j.Slf4j; +import rocks.inspectit.ocelot.bootstrap.Instances; import rocks.inspectit.ocelot.bootstrap.exposed.InspectitContext; import rocks.inspectit.ocelot.config.model.instrumentation.rules.RuleTracingSettings; +import rocks.inspectit.ocelot.core.instrumentation.autotracing.StackTraceSampler; import rocks.inspectit.ocelot.core.instrumentation.context.InspectitContextImpl; import rocks.inspectit.ocelot.core.instrumentation.hook.MethodReflectionInformation; import rocks.inspectit.ocelot.core.instrumentation.hook.VariableAccessor; @@ -16,12 +19,15 @@ import java.util.function.Predicate; /** - * Invokes {@link InspectitContextImpl#enterSpan(Span)} on the currently active context. + * Invokes {@link InspectitContextImpl#setSpanScope(AutoCloseable)} on the currently active context. */ @AllArgsConstructor @Builder +@Slf4j public class ContinueOrStartSpanAction implements IHookAction { + private StackTraceSampler stackTraceSampler; + /** * The variable accessor used to fetch the name for a newly began span. * Is configured using {@link RuleTracingSettings#getName()} @@ -66,6 +72,8 @@ public class ContinueOrStartSpanAction implements IHookAction { */ private Predicate startSpanCondition; + private final StackTraceSampler.Mode autoTrace; + /** * Action that optionally adds common tags to the newly started span. */ @@ -83,13 +91,16 @@ public void execute(ExecutionContext context) { } } - private boolean continueSpan(ExecutionContext context) { if (continueSpanDataKey != null && continueSpanCondition.test(context)) { InspectitContextImpl ctx = context.getInspectitContext(); Object spanObj = ctx.getData(continueSpanDataKey); if (spanObj instanceof Span) { - ctx.enterSpan((Span) spanObj); + MethodReflectionInformation methodInfo = context.getHook().getMethodInformation(); + AutoCloseable spanCtx = Instances.logTraceCorrelator.startCorrelatedSpanScope(() -> + stackTraceSampler.continueSpan((Span) spanObj, methodInfo, autoTrace) + ); + ctx.setSpanScope(spanCtx); return true; } } @@ -100,35 +111,26 @@ private void startSpan(ExecutionContext context) { if (startSpanCondition.test(context)) { // resolve span name InspectitContextImpl ctx = context.getInspectitContext(); - String spanName = getSpanName(context, context.getHook().getMethodInformation()); + + MethodReflectionInformation methodInfo = context.getHook().getMethodInformation(); + String spanName = getSpanName(context, methodInfo); // load remote parent if it exist SpanContext remoteParent = ctx.getAndClearCurrentRemoteSpanContext(); boolean hasLocalParent = false; - - // create builder based on the remote parent availability - SpanBuilder builder; - if (remoteParent != null) { - builder = Tracing.getTracer().spanBuilderWithRemoteParent(spanName, remoteParent); - } else { - final Span currentSpan = Tracing.getTracer().getCurrentSpan(); + if (remoteParent == null) { + Span currentSpan = Tracing.getTracer().getCurrentSpan(); hasLocalParent = currentSpan != BlankSpan.INSTANCE; - builder = Tracing.getTracer().spanBuilder(spanName); } - // resolve kind and sampler - builder.setSpanKind(spanKind); Sampler sampler = getSampler(context); - if (sampler != null) { - builder.setSampler(sampler); - } - - // start span and add common tags - final Span span = builder.startSpan(); - commonTagsToAttributesManager.writeCommonTags(span, remoteParent != null, hasLocalParent); + AutoCloseable spanCtx = Instances.logTraceCorrelator.startCorrelatedSpanScope(() -> + stackTraceSampler.createAndEnterSpan(spanName, remoteParent, sampler, spanKind, methodInfo, autoTrace) + ); + ctx.setSpanScope(spanCtx); + commonTagsToAttributesManager.writeCommonTags(Tracing.getTracer() + .getCurrentSpan(), remoteParent != null, hasLocalParent); - // enter in the our context - ctx.enterSpan(span); } } diff --git a/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/utils/HighPrecisionTimer.java b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/utils/HighPrecisionTimer.java new file mode 100644 index 0000000000..38e17dbb53 --- /dev/null +++ b/inspectit-ocelot-core/src/main/java/rocks/inspectit/ocelot/core/utils/HighPrecisionTimer.java @@ -0,0 +1,190 @@ +package rocks.inspectit.ocelot.core.utils; + +import com.google.common.annotations.VisibleForTesting; +import lombok.extern.slf4j.Slf4j; + +import java.time.Duration; +import java.util.concurrent.atomic.AtomicLong; +import java.util.concurrent.locks.LockSupport; +import java.util.function.BooleanSupplier; + +/** + * A timer for executing a task with a fixed delay with high precision. + * This class is designed with the following proeprties: + * - high precision of the timer (microsecond range) + * - very low overhead start() method to spin up the timer if called frequently + * - if the times idles for a long time, it is shutdown automatically (e.g. this timer costs no resources if not used) + *

+ * The timer executes a custom function returning a boolean. + * The return value hereby represents if any action was done. + * If no action is performed for a configurable amount of time, the timer automatically shuts down. + */ +@Slf4j +public class HighPrecisionTimer { + + /** + * The number of nanoseconds of inacitivity after which the timer shuts down. + */ + private volatile long maximumInactivityNanos; + + /** + * The period of the timer + */ + private volatile long periodNanos; + + /** + * A counter of how many timer executions have passed with no actions being performed ({@link #function} returned false) + */ + private AtomicLong inactivityCounter; + + /** + * As soon as {@link #inactivityLimit} reaches this value, the timer shuts itself down + */ + private volatile long inactivityLimit; + + /** + * The timer action to execute. + */ + private BooleanSupplier function; + + /** + * The timer runnable. + * Volatile because {@link #start()} could be called from different threads concurrently. + */ + private volatile TimerRunner timer; + + /** + * The name of the timer, used for the timer thread. + */ + private String name; + + /** + * True if {@link #destroy()} has been called. + */ + private boolean isDestroyed = false; + + public HighPrecisionTimer(String name, Duration period, Duration maximumInactivity, BooleanSupplier function) { + inactivityCounter = new AtomicLong(); + this.function = function; + this.name = name; + setPeriod(period); + setMaximumInactivity(maximumInactivity); + } + + /** + * Alters the timers period. Can be called while the timer is active. + * Won't wake-up the timer if it is sleeping for a longer period. + * + * @param duration the new period duration + */ + public synchronized void setPeriod(Duration duration) { + long newNanos = duration.toNanos(); + if (newNanos != periodNanos) { + periodNanos = newNanos; + inactivityLimit = (long) Math.ceil((double) maximumInactivityNanos / periodNanos); + } + } + + /** + * Alters the timers limit of inactivity time. + * As soon as the timer exceeds the configured limit, it is shut down. + * + * @param duration the new inactivity limit + */ + public synchronized void setMaximumInactivity(Duration duration) { + long newNanos = duration.toNanos(); + if (newNanos != maximumInactivityNanos) { + maximumInactivityNanos = newNanos; + inactivityLimit = (long) Math.ceil((double) maximumInactivityNanos / periodNanos); + inactivityCounter.set(0L); + } + } + + /** + * Ensures that the timer is running. + * This method is designed to be very low overhead if the timer is already running. + */ + public void start() { + //if we are still far enough away from the inactivity-limit there is no need to enter the synchronized block + if (timer == null || inactivityCounter.get() > inactivityLimit / 2) { + startTimerSynchronized(); + } else { + inactivityCounter.set(0L); + } + } + + @VisibleForTesting + synchronized boolean isStarted() { + return timer != null; + } + + @VisibleForTesting + synchronized void startTimerSynchronized() { + if (!isDestroyed) { + inactivityCounter.set(0L); + if (timer == null) { + timer = new TimerRunner(); + Thread runner = new Thread(timer); + runner.setDaemon(true); + runner.setName(name); + runner.start(); + } + } + } + + /** + * Destroys this timer. Subsequent {@link #start()} invocations will have no effect. + */ + public synchronized void destroy() { + isDestroyed = true; + if (timer != null && timer.runnerThread != null) { + timer.runnerThread.interrupt(); //interrupt sleeping + } + } + + private synchronized boolean shutdownAfterInactivity() { + if (inactivityCounter.get() >= inactivityLimit) { + timer = null; + return true; + } + return false; + } + + private class TimerRunner implements Runnable { + + private Thread runnerThread; + + @Override + public void run() { + log.info("Starting timer {}", name); + runnerThread = Thread.currentThread(); + while (!isDestroyed && !shutdownAfterInactivity()) { + long entryTimestamp = System.nanoTime(); + boolean workDone = false; + try { + workDone = function.getAsBoolean(); + } catch (Throwable t) { + log.error("Error executing timer function", t); + } + + if (!workDone) { + inactivityCounter.incrementAndGet(); + } else { + inactivityCounter.set(0L); + } + + sleepUntil(entryTimestamp + periodNanos); + } + log.debug("Stopping Timer {}", name); + } + + private void sleepUntil(long nanoTimestamp) { + long current = System.nanoTime(); + + while ((current < nanoTimestamp) && !isDestroyed) { + LockSupport.parkNanos(nanoTimestamp - current); + current = System.nanoTime(); + } + } + } +} \ No newline at end of file diff --git a/inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/CustomSpanBuilderTest.java b/inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/CustomSpanBuilderTest.java new file mode 100644 index 0000000000..d5108c39ef --- /dev/null +++ b/inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/CustomSpanBuilderTest.java @@ -0,0 +1,41 @@ +package rocks.inspectit.ocelot.core.instrumentation.autotracing; + +import io.opencensus.implcore.trace.RecordEventsSpanImpl; +import io.opencensus.trace.Span; +import io.opencensus.trace.Tracing; +import io.opencensus.trace.samplers.Samplers; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; + +import static org.assertj.core.api.Assertions.assertThat; + +public class CustomSpanBuilderTest { + + + @Nested + class Timestamps { + + @Test + void verifyTimingsChanged() { + + Span parent = Tracing.getTracer().spanBuilder("root") + .setSampler(Samplers.alwaysSample()) + .startSpan(); + + Span mySpan = CustomSpanBuilder.builder("foo", parent) + .customTiming(42, 142, null) + .startSpan(); + + RecordEventsSpanImpl spanImpl = (RecordEventsSpanImpl) mySpan; + assertThat(spanImpl.getName()).isEqualTo("foo"); + assertThat(spanImpl.getContext().getSpanId()).isNotEqualTo(parent.getContext().getSpanId()); + assertThat(spanImpl.getContext().getTraceId()).isEqualTo(parent.getContext().getTraceId()); + assertThat(spanImpl.getContext().getTraceOptions()).isEqualTo(parent.getContext().getTraceOptions()); + assertThat(spanImpl.getContext().getTracestate()).isEqualTo(parent.getContext().getTracestate()); + assertThat(spanImpl.toSpanData().getParentSpanId()).isEqualTo(parent.getContext().getSpanId()); + assertThat(spanImpl.getEndNanoTime()).isEqualTo(142); + assertThat(spanImpl.getLatencyNs()).isEqualTo(100); + } + } + +} diff --git a/inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/SampledTraceTest.java b/inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/SampledTraceTest.java new file mode 100644 index 0000000000..540812f0cf --- /dev/null +++ b/inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/SampledTraceTest.java @@ -0,0 +1,355 @@ +package rocks.inspectit.ocelot.core.instrumentation.autotracing; + +import io.opencensus.trace.Span; +import org.apache.commons.lang3.ArrayUtils; +import org.assertj.core.util.IterableUtil; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.mockito.Mockito; + +import java.util.ArrayList; +import java.util.Arrays; +import java.util.List; +import java.util.function.Consumer; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.mockito.Mockito.doReturn; + +public class SampledTraceTest { + + private static StackTrace createStackTrace(String... classMethods) { + StackTraceElement[] elements = Arrays.stream(classMethods) + .map(fqn -> new StackTraceElement(fqn.substring(0, fqn.lastIndexOf('.')), fqn.substring(fqn.lastIndexOf('.') + 1), null, -1)) + .toArray(StackTraceElement[]::new); + ArrayUtils.reverse(elements); + return new StackTrace(elements); + } + + private static abstract class SampledTraceGenerator { + + private List currentStack; + + private long fakeTime = 0; + + private SampledTrace traceToCreate; + + public SampledTraceGenerator(String... rootStackTrace) { + currentStack = new ArrayList<>(Arrays.asList(rootStackTrace)); + StackTrace rootTrace = createStackTrace(rootStackTrace); + traceToCreate = new SampledTrace(Mockito.mock(Span.class), () -> rootTrace); + } + + protected void sample() { + long time = fakeTime++; + StackTrace trace = createStackTrace(currentStack.toArray(new String[]{})); + traceToCreate.addStackTrace(trace, time); + } + + protected void anonymousCall(String name, Runnable action) { + currentStack.add(name); //add to fake call-stack + action.run(); + currentStack.remove(currentStack.size() - 1); + } + + protected void tracedCall(String name, Runnable action) { + long entryTime = fakeTime++; + PlaceholderSpan span = Mockito.mock(PlaceholderSpan.class); + doReturn(entryTime).when(span).getStartTime(); + doReturn(name).when(span).getSpanName(); + + currentStack.add(name); //add to fake call-stack + String className = name.substring(0, name.lastIndexOf('.')); + String methodName = name.substring(name.lastIndexOf('.') + 1); + SampledTrace.MethodExitNotifier exitCallback = traceToCreate.newSpanStarted(span, className, methodName); + + action.run(); + + currentStack.remove(currentStack.size() - 1); //pop from fake call stack + long exitTime = fakeTime++; + exitCallback.methodFinished(exitTime); + } + + public SampledTrace doGenerate() { + generate(); + return traceToCreate; + } + + abstract protected void generate(); + } + + private static class InvocationCheck implements Consumer { + + private String expectedName; + + private List childAsserts; + + private long entryTime; + + private long exitTime; + + public InvocationCheck(String expectedName, long entryTime, long exitTime, InvocationCheck... childAsserts) { + this.entryTime = entryTime; + this.exitTime = exitTime; + this.expectedName = expectedName; + this.childAsserts = Arrays.asList(childAsserts); + } + + @Override + public void accept(Invocation invocation) { + if (invocation.getSampledMethod() != null) { + assertThat(invocation.getSampledMethod().getClassName()) + .isEqualTo(expectedName.substring(0, expectedName.lastIndexOf('.'))); + assertThat(invocation.getSampledMethod().getMethodName()) + .isEqualTo(expectedName.substring(expectedName.lastIndexOf('.') + 1)); + } else { + assertThat(invocation.getPlaceholderSpan().getSpanName()).isEqualTo(expectedName); + } + assertThat(invocation.getStart().getTimestamp()).isEqualTo(entryTime); + assertThat(invocation.getEnd().getTimestamp()).isEqualTo(exitTime); + assertThat(invocation.getChildren()).hasSize(childAsserts.size()); + Object[] children = IterableUtil.toArray(invocation.getChildren()); + for (int i = 0; i < children.length; i++) { + childAsserts.get(i).accept((Invocation) children[i]); + } + } + } + + @Nested + class GenerateInvocations { + + @Test + void singleSampleMethodsIgnored() { + SampledTrace trace = new SampledTraceGenerator("RootA.myRootA", "RootA.myRootB") { + @Override + protected void generate() { + anonymousCall("Top.firstMethod", () -> { + anonymousCall("Child.meth1", () -> { + sample(); + }); + anonymousCall("Child.meth2", () -> { + sample(); + }); + }); + } + }.doGenerate(); + + Iterable invocations = trace.generateInvocations(); + assertThat(invocations).hasSize(1); + assertThat(invocations).first().satisfies( + new InvocationCheck("Top.firstMethod", 0, 1) + ); + } + + @Test + void dualSampleMethodsRespected() { + SampledTrace trace = new SampledTraceGenerator("RootA.myRootA", "RootA.myRootB") { + @Override + protected void generate() { + sample(); + anonymousCall("Top.firstMethod", () -> { + anonymousCall("Child.meth0", () -> { + sample(); + }); + anonymousCall("Child.meth1", () -> { + sample(); + sample(); + }); + anonymousCall("Child.meth2", () -> { + sample(); + sample(); + }); + }); + } + }.doGenerate(); + + Iterable invocations = trace.generateInvocations(); + assertThat(invocations).hasSize(1); + assertThat(invocations).first().satisfies( + new InvocationCheck("Top.firstMethod", 1, 5, + new InvocationCheck("Child.meth1", 2, 3), + new InvocationCheck("Child.meth2", 4, 5) + ) + ); + } + + @Test + void multipleRoots() { + SampledTrace trace = new SampledTraceGenerator("RootA.myRootA", "RootA.myRootB") { + @Override + protected void generate() { + anonymousCall("Top.firstMethod", () -> { + sample(); + sample(); + }); + tracedCall("Hello.secondMethod", () -> { + }); + } + }.doGenerate(); + + Iterable invocations = trace.generateInvocations(); + assertThat(invocations).hasSize(2); + assertThat(invocations).first().satisfies( + new InvocationCheck("Top.firstMethod", 0, 1) + ); + assertThat(invocations).last().satisfies( + new InvocationCheck("Hello.secondMethod", 2, 3) + ); + } + + @Test + void instrumentedMethodWithSampledChild() { + SampledTrace trace = new SampledTraceGenerator("RootA.myRootA", "RootA.myRootB") { + @Override + protected void generate() { + tracedCall("Instr.methA", () -> { + anonymousCall("Sampled.methB", () -> { + sample(); + anonymousCall("Sampled.methC", () -> { + sample(); + sample(); + }); + }); + }); + } + }.doGenerate(); + + Iterable invocations = trace.generateInvocations(); + assertThat(invocations).hasSize(1); + assertThat(invocations).first().satisfies( + new InvocationCheck("Instr.methA", 0, 4, + new InvocationCheck("Sampled.methB", 1, 3, + new InvocationCheck("Sampled.methC", 2, 3))) + ); + } + + @Test + void nestedInstrumentations() { + SampledTrace trace = new SampledTraceGenerator("RootA.myRootA", "RootA.myRootB") { + @Override + protected void generate() { + anonymousCall("Top.firstMethod", () -> { + sample(); + tracedCall("A.a1", () -> { + tracedCall("B.b1", () -> { + sample(); + }); + }); + }); + } + }.doGenerate(); + + Iterable invocations = trace.generateInvocations(); + assertThat(invocations).hasSize(1); + assertThat(invocations).first().satisfies( + new InvocationCheck("Top.firstMethod", 0, 5, + new InvocationCheck("A.a1", 1, 5, + new InvocationCheck("B.b1", 2, 4) + ) + ) + ); + } + + @Test + void instrumentedMethodWithSingleSampleParent() { + SampledTrace trace = new SampledTraceGenerator("RootA.myRootA", "RootA.myRootB") { + @Override + protected void generate() { + anonymousCall("Top.firstMethod", () -> { + tracedCall("A.a1", () -> { + sample(); + }); + }); + } + }.doGenerate(); + + Iterable invocations = trace.generateInvocations(); + assertThat(invocations).hasSize(1); + assertThat(invocations).first().satisfies( + new InvocationCheck("Top.firstMethod", 0, 2, + new InvocationCheck("A.a1", 0, 2) + ) + ); + } + + @Test + void instrumentedMethodWithMultipleSampleParent() { + SampledTrace trace = new SampledTraceGenerator("RootA.myRootA", "RootA.myRootB") { + @Override + protected void generate() { + anonymousCall("Top.firstMethod", () -> { + anonymousCall("Blub.secondMethod", () -> { + tracedCall("A.a1", () -> { + sample(); + }); + }); + }); + } + }.doGenerate(); + + Iterable invocations = trace.generateInvocations(); + assertThat(invocations).hasSize(1); + assertThat(invocations).first().satisfies( + new InvocationCheck("Top.firstMethod", 0, 2, + new InvocationCheck("Blub.secondMethod", 0, 2, + new InvocationCheck("A.a1", 0, 2) + ) + ) + ); + } + + @Test + void instrumentedMethodWithExtendedParent() { + SampledTrace trace = new SampledTraceGenerator("RootA.myRootA", "RootA.myRootB") { + @Override + protected void generate() { + anonymousCall("Top.firstMethod", () -> { + tracedCall("A.a1", () -> { + sample(); + }); + sample(); + sample(); + }); + } + }.doGenerate(); + + Iterable invocations = trace.generateInvocations(); + assertThat(invocations).hasSize(1); + assertThat(invocations).first().satisfies( + new InvocationCheck("Top.firstMethod", 0, 4, + new InvocationCheck("A.a1", 0, 2) + ) + ); + } + + @Test + void recursiveInstrumentations() { + SampledTrace trace = new SampledTraceGenerator("RootA.myRootA", "RootA.myRootB") { + @Override + protected void generate() { + anonymousCall("Top.firstMethod", () -> { + tracedCall("Do.recurse", () -> { + anonymousCall("Middle.myMethod", () -> { + tracedCall("Do.recurse", () -> { + sample(); + }); + }); + }); + }); + } + }.doGenerate(); + + Iterable invocations = trace.generateInvocations(); + assertThat(invocations).hasSize(1); + assertThat(invocations).first().satisfies( + new InvocationCheck("Top.firstMethod", 0, 4, + new InvocationCheck("Do.recurse", 0, 4, + new InvocationCheck("Middle.myMethod", 1, 3, + new InvocationCheck("Do.recurse", 1, 3)) + ) + ) + ); + } + + } + +} diff --git a/inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/StackTraceTest.java b/inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/StackTraceTest.java new file mode 100644 index 0000000000..0ee99bc7ef --- /dev/null +++ b/inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/instrumentation/autotracing/StackTraceTest.java @@ -0,0 +1,52 @@ +package rocks.inspectit.ocelot.core.instrumentation.autotracing; + +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; + +import static org.assertj.core.api.Assertions.assertThat; + +public class StackTraceTest { + + @Nested + static class Cleanup { + + @Test + void verifyStackTopCleaned() { + StackTraceElement rootFrame = new StackTraceElement("Root", "rootMethod", "", -1); + StackTraceElement calleeFrame = new StackTraceElement("Callee", "callee", "", -1); + StackTraceElement[] input = { + new StackTraceElement("rocks.inspectit.ocelot.bootstrap.Instances", "getSome", "", -1), + new StackTraceElement("rocks.inspectit.ocelot.core.SomeClass", "doStuff", "", -1), + calleeFrame, + rootFrame, + }; + + StackTrace st = new StackTrace(input); + + assertThat(st.size()).isEqualTo(2); + assertThat(st.get(0)).isSameAs(rootFrame); + assertThat(st.get(1)).isSameAs(calleeFrame); + } + + @Test + void verifyLambdaRemoved() { + Runnable r1 = () -> { + }; + StackTraceElement rootFrame = new StackTraceElement("Root", "rootMethod", "", -1); + StackTraceElement calleeFrame = new StackTraceElement("Callee", "callee", "", -1); + StackTraceElement[] input = { + new StackTraceElement("rocks.inspectit.ocelot.bootstrap.Instances", "getSome", "", -1), + calleeFrame, + new StackTraceElement("not." + r1.getClass().getName(), "run", "", -1), + rootFrame, + }; + + StackTrace st = new StackTrace(input); + + assertThat(st.size()).isEqualTo(2); + assertThat(st.get(0)).isSameAs(rootFrame); + assertThat(st.get(1)).isSameAs(calleeFrame); + } + + } +} diff --git a/inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/instrumentation/context/InspectitContextImplTest.java b/inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/instrumentation/context/InspectitContextImplTest.java index 499c03de92..b349d8238d 100644 --- a/inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/instrumentation/context/InspectitContextImplTest.java +++ b/inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/instrumentation/context/InspectitContextImplTest.java @@ -93,9 +93,7 @@ void spanEntered() { InspectitContextImpl ctx = InspectitContextImpl.createFromCurrent(new HashMap<>(), propagation, false); assertThat(ctx.hasEnteredSpan()).isFalse(); - ctx.enterSpan(mySpan); - - verify(traceCorrelator).startCorrelatedSpanScope(any()); + ctx.setSpanScope(Tracing.getTracer().withSpan(mySpan)); ctx.makeActive(); @@ -946,7 +944,7 @@ public class SpanActivation { void verifySpanAttachedAndDetached() { InspectitContextImpl ctx = InspectitContextImpl.createFromCurrent(Collections.emptyMap(), propagation, true); Span sp = Tracing.getTracer().spanBuilder("blub").startSpan(); - ctx.enterSpan(sp); + ctx.setSpanScope(Tracing.getTracer().withSpan(sp)); ctx.makeActive(); Span span = Tracing.getTracer().getCurrentSpan(); diff --git a/inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/util/HighPrecisionTimerTest.java b/inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/util/HighPrecisionTimerTest.java new file mode 100644 index 0000000000..7150c5f7cd --- /dev/null +++ b/inspectit-ocelot-core/src/test/java/rocks/inspectit/ocelot/core/util/HighPrecisionTimerTest.java @@ -0,0 +1,91 @@ +package rocks.inspectit.ocelot.core.utils; + +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.Nested; +import org.junit.jupiter.api.Test; +import org.mockito.Mockito; + +import java.time.Duration; +import java.util.function.BooleanSupplier; + +import static org.mockito.Mockito.*; + +public class HighPrecisionTimerTest { + + private HighPrecisionTimer timer; + + private void createSpyTimer(long periodMillis, long inactivityLimitMillis, BooleanSupplier function) { + timer = Mockito.spy(new HighPrecisionTimer("test", Duration.ofMillis(periodMillis), Duration.ofMillis(inactivityLimitMillis), function)); + } + + @AfterEach + void cleanUp() { + timer.destroy(); + } + + private void sleepAtLeast(long ms) { + long start = System.nanoTime(); + while ((System.nanoTime() - start) < ms * 1000 * 1000) { + long slept = (System.nanoTime() - start) / 1000 / 1000; + try { + Thread.sleep(ms - slept); + } catch (InterruptedException e) { + throw new RuntimeException(e); + } + } + } + + @Nested + class Start { + + @Test + void verifyStartResetsInactivity() { + createSpyTimer(1, 100, () -> false); + for (int i = 0; i < 10; i++) { + timer.start(); + sleepAtLeast(20); + } + verify(timer).startTimerSynchronized(); + } + + + @Test + void verifyActionCalled() { + BooleanSupplier action = mock(BooleanSupplier.class); + doReturn(true).when(action).getAsBoolean(); + + createSpyTimer(1, 10, action); + + timer.start(); + sleepAtLeast(50); + + verify(action, atLeastOnce()).getAsBoolean(); + } + + @Test + void verifyActionResetsInactivity() { + createSpyTimer(1, 10, () -> true); + + timer.start(); + sleepAtLeast(50); + timer.start(); + + verify(timer).startTimerSynchronized(); + } + + @Test + void verifyRestartAfterInactivity() { + createSpyTimer(1, 100, () -> false); + for (int i = 0; i < 2; i++) { + timer.start(); + } + verify(timer).startTimerSynchronized(); + + sleepAtLeast(150); + for (int i = 0; i < 2; i++) { + timer.start(); + } + verify(timer, times(2)).startTimerSynchronized(); + } + } +} \ No newline at end of file diff --git a/inspectit-ocelot-documentation/docs/breaking-changes/1.6.md b/inspectit-ocelot-documentation/docs/breaking-changes/1.6.md new file mode 100644 index 0000000000..ef8ae3125b --- /dev/null +++ b/inspectit-ocelot-documentation/docs/breaking-changes/1.6.md @@ -0,0 +1,6 @@ +--- +id: 1-6 +title: Breaking changes in 1.6 +--- + +There are no breaking changes for version 1.6. \ No newline at end of file diff --git a/inspectit-ocelot-documentation/docs/instrumentation/rules.md b/inspectit-ocelot-documentation/docs/instrumentation/rules.md index dcc9695913..b86a7ecd7a 100644 --- a/inspectit-ocelot-documentation/docs/instrumentation/rules.md +++ b/inspectit-ocelot-documentation/docs/instrumentation/rules.md @@ -564,7 +564,7 @@ This is done via the `error-status` configuration property of a rule's tracing s inspectit: instrumentation: rules: - 'r_example_rule"': + 'r_example_rule': tracing: start-span: true error-status: _thrown @@ -605,6 +605,49 @@ If any `start-span-conditions` are defined, a span will only be created when all Analogous to this, attributes will only be written if each condition defined in `attribute-conditions` is fulfilled. The conditions that can be defined are equal to the ones of actions, thus, please see the [action conditions description](#adding-conditions) for detailed information. +#### Auto-Tracing + +With the shown approach traces will only contain exactly the methods you instrumented. +Often however, one observes certain methods taking a long time without knowing where exactly the time is spent. +The "auto-tracing" feature can be used to solve this problem. + +When auto-tracing is enabled, inspectIT uses a profiler-like approach for recording traces. +With auto-tracing, stack traces of threads are collected periodically. Based on these samples, inspectIT will reconstruct +an approximate trace showing where the time was spent. + +> This feature is currently experimental and can potentially have a high performance impact. We do not recommend using it for production environments yet! + +Auto-tracing can be enabled on methods which are traced using either the `start-span` or `continue-span` options. +To enable it you can simply add the `auto-tracing` setting: + +```yaml +inspectit: + instrumentation: + rules: + 'r_example_rule': + tracing: + start-span: true + auto-tracing: true +``` + +When auto-tracing is enabled, callees of the method will be traced by periodically capturing stack traces. +Methods recorded via auto-tracing will be marked in the traces by a leading asterisk. + +You can also set the `auto-tracing` option to `false`, which disables auto-tracing for the methods affected by this rule. +In this case any active `auto-traces` will be paused for the duration of the method, no samples will be recorded. + +The frequency at which stack trace samples are captured is defined globally: +```yaml +inspectit: + tracing: + auto-tracing: + frequency: 50ms +``` + +This setting specifies that each thread for which auto-tracing is enabled will be stopped every 50ms in order to capture a stack trace. +It also implicitly defines the granularity of your traces: Only methods with at least this duration will appear in your traces. + + #### Tracing Asynchronous Invocations With the previous shown settings, it is possible to add an instrumentation which creates exactly one span per invocation of an instrumented method. diff --git a/inspectit-ocelot-documentation/website/sidebars.json b/inspectit-ocelot-documentation/website/sidebars.json index a334e1bf4b..1567a63bc3 100644 --- a/inspectit-ocelot-documentation/website/sidebars.json +++ b/inspectit-ocelot-documentation/website/sidebars.json @@ -49,6 +49,7 @@ "config-server/log-config" ], "Breaking Changes": [ + "breaking-changes/1-6", "breaking-changes/1-5", "breaking-changes/1-4", "breaking-changes/1-3",