Skip to content

Commit

Permalink
Add start/stop OpCodes to SdkEventSource ActivityStart/Stop events
Browse files Browse the repository at this point in the history
Renamed ActivityStarted/Stopped to ActivityStart/Stop
Add tests
Prevent concurrent execution of EventSource tests
  • Loading branch information
pharring committed Feb 24, 2024
1 parent 73b6e30 commit a3c6dea
Show file tree
Hide file tree
Showing 5 changed files with 132 additions and 9 deletions.
12 changes: 6 additions & 6 deletions src/OpenTelemetry/Internal/OpenTelemetrySdkEventSource.cs
Original file line number Diff line number Diff line change
Expand Up @@ -69,7 +69,7 @@ public void ActivityStarted(Activity activity)
// https:/dotnet/runtime/issues/61857
var activityId = string.Concat("00-", activity.TraceId.ToHexString(), "-", activity.SpanId.ToHexString());
activityId = string.Concat(activityId, activity.ActivityTraceFlags.HasFlag(ActivityTraceFlags.Recorded) ? "-01" : "-00");
this.ActivityStarted(activity.DisplayName, activityId);
this.ActivityStart(activity.DisplayName, activityId);
}
}

Expand All @@ -78,7 +78,7 @@ public void ActivityStopped(Activity activity)
{
if (this.IsEnabled(EventLevel.Verbose, EventKeywords.All))
{
this.ActivityStopped(activity.DisplayName, activity.Id);
this.ActivityStop(activity.DisplayName, activity.Id);
}
}

Expand Down Expand Up @@ -175,14 +175,14 @@ public void ObservableInstrumentCallbackException(string exception)
this.WriteEvent(16, exception);
}

[Event(24, Message = "Activity started. Name = '{0}', Id = '{1}'.", Level = EventLevel.Verbose)]
public void ActivityStarted(string name, string id)
[Event(24, Message = "Activity started. Name = '{0}', Id = '{1}'.", Level = EventLevel.Verbose, Opcode = EventOpcode.Start)]
public void ActivityStart(string name, string id)
{
this.WriteEvent(24, name, id);
}

[Event(25, Message = "Activity stopped. Name = '{0}', Id = '{1}'.", Level = EventLevel.Verbose)]
public void ActivityStopped(string name, string? id)
[Event(25, Message = "Activity stopped. Name = '{0}', Id = '{1}'.", Level = EventLevel.Verbose, Opcode = EventOpcode.Stop)]
public void ActivityStop(string name, string? id)
{
this.WriteEvent(25, name, id);
}
Expand Down
2 changes: 1 addition & 1 deletion test/Benchmarks/EventSourceBenchmarks.cs
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,7 @@ public void EventWithIdAllocation()
activity.Start();
activity.Stop();

OpenTelemetrySdkEventSource.Log.ActivityStarted(activity.OperationName, activity.Id);
OpenTelemetrySdkEventSource.Log.ActivityStart(activity.OperationName, activity.Id);
}

[Benchmark]
Expand Down
1 change: 1 addition & 0 deletions test/OpenTelemetry.Tests/EventSourceTest.cs
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@

namespace OpenTelemetry.Tests;

[Collection("Uses-OpenTelemetrySdkEventSource")] // Prevent parallel execution with other tests that exercise the SdkEventSource
public class EventSourceTest
{
[Fact]
Expand Down
121 changes: 121 additions & 0 deletions test/OpenTelemetry.Tests/Internal/SdkEventSourceTest.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,121 @@
// Copyright The OpenTelemetry Authors
// SPDX-License-Identifier: Apache-2.0
#nullable enable

using System.Diagnostics;
using System.Diagnostics.Tracing;
using OpenTelemetry.Internal;
using OpenTelemetry.Trace;
using Xunit;

namespace OpenTelemetry.Tests.Internal;

[Collection("Uses-OpenTelemetrySdkEventSource")] // Prevent parallel execution with other tests that exercise the SdkEventSource
public class SdkEventSourceTest : IDisposable
{
private readonly SdkEventListener listener = new();

public void Dispose()
{
this.listener.Dispose();
}

[Fact]
public void ActivityStartUsesOpCodeStart()
{
using (TracerProvider tracerProvider = Sdk.CreateTracerProviderBuilder()
.AddSource("TestSource")
.Build())
{
// Clear any events that were emitted during Build.
this.listener.Events.Clear();

const int numActivities = 4;

using ActivitySource activitySource = new("TestSource");
for (int i = 0; i < numActivities; i++)
{
using Activity? activity = activitySource.StartActivity($"Test Activity {i}");
}

// There should be 2 events for each activity: ActivityStart and ActivityStop.
Assert.Equal(numActivities * 2, this.listener.Events.Count);

HashSet<Guid> activityIds = [];
for (int i = 0; i < numActivities; i++)
{
EventWrittenEventArgs startEvent = this.listener.Events[i * 2];
EventWrittenEventArgs stopEvent = this.listener.Events[(i * 2) + 1];

Assert.Equal(nameof(OpenTelemetrySdkEventSource.ActivityStart), startEvent.EventName);
Assert.Equal(nameof(OpenTelemetrySdkEventSource.ActivityStop), stopEvent.EventName);

// Start and Stop should be matched on ActivityId.
Assert.Equal(startEvent.ActivityId, stopEvent.ActivityId);

// ActivityIds should be unique.
Assert.True(activityIds.Add(startEvent.ActivityId));
}
}
}

private sealed class SdkEventListener : EventListener
{
private static readonly string SdkEventSourceName = EventSource.GetName(typeof(OpenTelemetrySdkEventSource));
private readonly HashSet<EventSource> eventSourcesEnabled = [];

public List<EventWrittenEventArgs> Events { get; } = [];

public override void Dispose()
{
try
{
foreach (EventSource eventSource in this.eventSourcesEnabled)
{
this.DisableEvents(eventSource);
}
}
finally
{
base.Dispose();
}
}

protected override void OnEventSourceCreated(EventSource eventSource)
{
if (eventSource.Name == SdkEventSourceName)
{
this.eventSourcesEnabled.Add(eventSource);
this.EnableEvents(eventSource, EventLevel.Verbose, EventKeywords.All);
}
else if (eventSource.Name == "System.Threading.Tasks.TplEventSource")
{
// In addition to the OpenTelemetrySdkEventSource we need
// the TPL EventSource to enable activity tracking. When
// enabled and an EventSource writes events with
// EventOpCode.Start/Stop, then the ActivityTracker will
// generate new path-like ActivityIDs.
// Also note that activity tracking requires that the
// Start/Stop events are a matched pair, named like
// "xyzStart" and "xyzStop". ActivityTracker matches the
// stop event with the start event by recognizing those
// exact suffixes.
this.eventSourcesEnabled.Add(eventSource);
const EventKeywords taskFlowActivityIds = (EventKeywords)0x80;
this.EnableEvents(eventSource, EventLevel.Informational, taskFlowActivityIds);
}

base.OnEventSourceCreated(eventSource);
}

protected override void OnEventWritten(EventWrittenEventArgs eventData)
{
if (eventData.EventSource.Name == SdkEventSourceName)
{
this.Events.Add(eventData);
}

base.OnEventWritten(eventData);
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@

namespace OpenTelemetry.Internal.Tests;

[Collection("Uses-OpenTelemetrySdkEventSource")] // Prevent parallel execution with other tests that exercise the SdkEventSource
public class SelfDiagnosticsEventListenerTest
{
private const string LOGFILEPATH = "Diagnostics.log";
Expand All @@ -32,7 +33,7 @@ public void SelfDiagnosticsEventListener_EventSourceSetup_LowerSeverity()
_ = new SelfDiagnosticsEventListener(EventLevel.Error, configRefresher);

// Emitting a Verbose event. Or any EventSource event with lower severity than Error.
OpenTelemetrySdkEventSource.Log.ActivityStarted("Activity started", "1");
OpenTelemetrySdkEventSource.Log.ActivityStart("Activity started", "1");
Assert.False(configRefresher.TryGetLogStreamCalled);
}

Expand Down Expand Up @@ -115,7 +116,7 @@ public void SelfDiagnosticsEventListener_EmitEvent_OmitAsConfigured()
_ = new SelfDiagnosticsEventListener(EventLevel.Error, configRefresher);

// Act: emit an event with severity lower than configured
OpenTelemetrySdkEventSource.Log.ActivityStarted("ActivityStart", "123");
OpenTelemetrySdkEventSource.Log.ActivityStart("ActivityStart", "123");

// Assert
Assert.False(configRefresher.TryGetLogStreamCalled);
Expand Down

0 comments on commit a3c6dea

Please sign in to comment.