Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add log level and keyword tests for NativeRuntimeEventSource #89816

Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 3 additions & 0 deletions src/tests/issues.targets
Original file line number Diff line number Diff line change
Expand Up @@ -3403,6 +3403,9 @@
<ExcludeList Include = "$(XunitTestBinBase)/tracing/eventpipe/enabledisable/**">
<Issue> needs triage </Issue>
</ExcludeList>
<ExcludeList Include = "$(XunitTestBinBase)/tracing/runtimeeventsource/nativeruntimelevelkeywords/**">
<Issue>needs triage</Issue>
</ExcludeList>
<ExcludeList Include = "$(XunitTestBinBase)/Exceptions/ForeignThread/ForeignThreadExceptions/**">
<Issue>needs triage</Issue>
</ExcludeList>
Expand Down
136 changes: 136 additions & 0 deletions src/tests/tracing/runtimeeventsource/NativeRuntimeLevelKeywords.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,136 @@
using System;
using System.Collections.Concurrent;
using System.Collections.Generic;
using System.Diagnostics;
using System.Diagnostics.Tracing;
using System.Linq;

using System.Buffers; // Copied from https://github.com/dotnet/runtime/pull/86370 by @davmason:
{
// Access ArrayPool.Shared.Rent() before the test to avoid the deadlock reported
// in https://github.com/dotnet/runtime/issues/86233. This is a real issue,
// but only seen if you have a short lived EventListener and create EventSources
// in your OnEventWritten callback so we don't expect customers to hit it.
byte[] localBuffer = ArrayPool<byte>.Shared.Rent(10);
Console.WriteLine($"buffer length={localBuffer.Length}");
}
Console.WriteLine();

using GCListener informational = GCListener.StartNew(EventLevel.Informational);
using GCListener verbose = GCListener.StartNew(EventLevel.Verbose);
using GCListener logAlways = GCListener.StartNew(EventLevel.LogAlways);

Stopwatch stopwatch = Stopwatch.StartNew();
do
{
int nanoseconds = (int)double.Min(stopwatch.Elapsed.TotalNanoseconds, 1000000d);

for (int i = 0; i < nanoseconds; i++)
{
_ = new object();
}
GC.Collect();

if (informational.Contains("GCStart_V2") && verbose.Contains("GCAllocationTick_V4"))
Copy link
Member

@lateralusX lateralusX Aug 28, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe you should pick some events that is supported by Mono runtime? The GCStart_V2 is supported when requesting full GC dumps (but currently won't be emitted if you just use event mask 1) and GCAllocationTick_V4 is not supported at all on Mono runtime. https://github.com/dotnet/runtime/blob/main/src/mono/mono/eventpipe/gen-eventing-event-inc.lst lists the native runtime event currently supported by Mono runtime. Mono runtime also supports all managed events emitted through EventSource implementations in BCL (and custom defined EventSource classes). If you don't find any suitable events around supported once, you will need to exclude this test on Mono runtime altogether, but would be really good to test it on Mono runtime as well. One option could be to request a GC dump and collect generated events from that, see https://github.com/dotnet/runtime/blob/main/src/tests/tracing/eventpipe/gcdump/gcdump.cs, that test runs on Mono desktop platforms. You can also look in issues.targets for that test and make sure it disabled on the same set of platforms to make sure it won't break runtime extra platforms lane on CI.

{
break;
}
}
while (stopwatch.Elapsed.TotalSeconds <= 0.25d);

GCListener.DumpEvents(informational, verbose, logAlways);

Console.WriteLine($"\nElapsed Seconds: {stopwatch.Elapsed.TotalSeconds}\n");

AssertContains("GCStart_V2", EventLevel.Informational, informational, verbose, logAlways);
AssertContains("GCAllocationTick_V4", EventLevel.Verbose, informational, verbose, logAlways);

return 100;

static void AssertContains(string eventName, EventLevel level, params GCListener[] listeners)
{
int eventLevel = (level is EventLevel.LogAlways) ? int.MinValue : (int)level;

foreach (GCListener listener in listeners)
{
int listenerLevel = (listener.Level is EventLevel.LogAlways) ? int.MaxValue : (int)listener.Level;

if ((eventLevel > listenerLevel) && listener.Contains(eventName))
{
throw new Exception($"{eventName} is in {listener}");
}
else if ((eventLevel <= listenerLevel) && !listener.Contains(eventName))
{
throw new Exception($"{eventName} is not in {listener}");
}
}
}

internal sealed class GCListener : EventListener
{
public EventLevel Level { get; private set; }

private static EventLevel nextLevel;
private readonly ConcurrentDictionary<string, (int id, EventLevel level)> events = new();
private bool eventsReceived = false;

private GCListener()
{
Console.WriteLine($"{this} Listening...");
}

public static GCListener StartNew(EventLevel level)
{
nextLevel = level;
return new();
}

public static void DumpEvents(params GCListener[] listeners)
{
foreach (GCListener listener in listeners)
{
Console.WriteLine($"\n{listener} Dump:\n\\");

foreach (KeyValuePair<string, (int id, EventLevel level)> e in listener.events.OrderBy(e =>
{
return e.Value.id;
}))
{
Console.WriteLine($"{e.Value.id,3}: {$"\"{e.Key}\"",-24}, EventLevel.{e.Value.level,-13}");
}
}
}
public bool Contains(string eventName)
{
return events.ContainsKey(eventName);
}
public override string ToString()
{
return $"{nameof(GCListener)}({Level,-13}, {eventsReceived,-5}, {events.Count,2})";
}
public override void Dispose()
{
Console.WriteLine($"{this} Disposing... ");
base.Dispose();
}

protected override void OnEventSourceCreated(EventSource source)
{
if (source.Name is "Microsoft-Windows-DotNETRuntime")
{
Level = nextLevel;
EnableEvents(source, Level, (EventKeywords)1);
}
}
protected override void OnEventWritten(EventWrittenEventArgs e)
{
events.TryAdd(e.EventName ?? "", (e.EventId, e.Level));

if (eventsReceived)
{
return;
}
eventsReceived = true;
Console.WriteLine($"{this} Events Received");
}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,15 @@
<Project Sdk="Microsoft.NET.Sdk">
<PropertyGroup>
<OutputType>Exe</OutputType>
<AllowUnsafeBlocks>true</AllowUnsafeBlocks>
<!-- Tracing tests routinely time out with jitstress and gcstress -->
<GCStressIncompatible>true</GCStressIncompatible>
<JitOptimizationSensitive>true</JitOptimizationSensitive>
<!-- This test has a secondary thread with an infinite loop -->
<UnloadabilityIncompatible>true</UnloadabilityIncompatible>
</PropertyGroup>
<ItemGroup>
<Compile Include="NativeRuntimeLevelKeywords.cs" />
<ProjectReference Include="../common/common.csproj" />
</ItemGroup>
</Project>