Add log level and keyword tests for NativeRuntimeEventSource #89816

nickyMcDonald · 2023-08-01T22:26:31Z

Tests are designed to catch possible regressions for EventLevel.LogAlways & EventKeywords.None after #89326.

EventKeywords.None sould be equivalent to EventKeywords.All.
EventLevel.LogAlways sould be equivalent to or greater then EventLevel.Verbose.

tommcdon · 2023-08-02T01:54:41Z

Test failures seem to be due to a deadlock/hang in the test with the following callstacks. @davmason is this related to dotnet/diagnostics#4825?

> clrstack -all
OS Thread Id: 0x26dc
        Child SP               IP Call Site
000000592F97D738 00007ffbf1ea67e4 [HelperMethodFrame_1OBJ: 000000592f97d738] System.Threading.Monitor.ObjWait(Int32, System.Object)
000000592F97D860 00007FFBBED4390E System.Threading.Monitor.Wait(System.Object, Int32)
000000592F97D890 00007FFBBED4FC0A System.Threading.ManualResetEventSlim.Wait(Int32, System.Threading.CancellationToken)
000000592F97D930 00007FFBBED6C599 System.Threading.Tasks.Task.SpinThenBlockingWait(Int32, System.Threading.CancellationToken)
000000592F97D9B0 00007FFBBED6C3F9 System.Threading.Tasks.Task.InternalWaitCore(Int32, System.Threading.CancellationToken)
000000592F97DA30 00007FFBBED6BF43 System.Threading.Tasks.Task.Wait(Int32, System.Threading.CancellationToken)
000000592F97DA60 00007FFBBED6BE02 System.Threading.Tasks.Task.Wait()
000000592F97DA90 00007FFBBEE7375D System.Diagnostics.Tracing.EventPipeEventDispatcher.StopDispatchTask()
000000592F97DB60 00007FFBBEE73435 System.Diagnostics.Tracing.EventPipeEventDispatcher.CommitDispatchConfiguration()
000000592F97DC60 00007FFBBEE7324A System.Diagnostics.Tracing.EventPipeEventDispatcher.SendCommand(System.Diagnostics.Tracing.EventListener, System.Diagnostics.Tracing.EventCommand, Boolean, System.Diagnostics.Tracing.EventLevel, System.Diagnostics.Tracing.EventKeywords)
000000592F97DCF0 00007FFB86B8388B Listener.OnEventSourceCreated(System.Diagnostics.Tracing.EventSource)
000000592F97DD70 00007FFBBEE810A8 System.Diagnostics.Tracing.EventSource.AddListener(System.Diagnostics.Tracing.EventListener)
000000592F97DDE0 00007FFBBEE84E8A System.Diagnostics.Tracing.EventListener.CallBackForExistingEventSources(Boolean, System.EventHandler`1<System.Diagnostics.Tracing.EventSourceCreatedEventArgs>)
000000592F97DE80 00007FFB86B8372F Listener..ctor()
000000592F97DEC0 00007FFB86B82DCC Program.<Main>$(System.String[])
OS Thread Id: 0x264c
        Child SP               IP Call Site
00000059300FFBF8 00007ffbf1ea67e4 [DebuggerU2MCatchHandlerFrame: 00000059300ffbf8]
OS Thread Id: 0x2650
        Child SP               IP Call Site
00000059303FCEE8 00007ffbf1ea67e4 [HelperMethodFrame_1OBJ: 00000059303fcee8] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
00000059303FD260 00007FFBBEE7BF19 System.Diagnostics.Tracing.EventSource.Initialize(System.Guid, System.String, System.String[])
00000059303FD300 00007FFBBED38639 System.Buffers.ArrayPoolEventSource..ctor()
00000059303FD350 00007FFBBED38687 System.Buffers.ArrayPoolEventSource..cctor()
00000059303FE9E0 00007ffbe644b983 [DynamicHelperFrame: 00000059303fe9e0]
00000059303FEB80 00007FFBBEEC58E2 System.Buffers.SharedArrayPool`1[[System.Char, System.Private.CoreLib]].Rent(Int32)
00000059303FEC10 00007FFB86B86845 Listener.OnEventWritten(System.Diagnostics.Tracing.EventWrittenEventArgs)
00000059303FEC90 00007FFBBEE7D42D System.Diagnostics.Tracing.EventSource.DispatchToAllListeners(System.Diagnostics.Tracing.EventWrittenEventArgs)
00000059303FECF0 00007FFBBEE6E6A8 System.Diagnostics.Tracing.NativeRuntimeEventSource.ProcessEvent(UInt32, UInt32, System.DateTime, System.Guid, System.Guid, System.ReadOnlySpan`1<Byte>)
00000059303FED60 00007FFBBEE73857 System.Diagnostics.Tracing.EventPipeEventDispatcher.DispatchEventsToEventListeners()
00000059303FEED0 00007FFBBED4D1AD System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
00000059303FEF40 00007FFBBED6B55F System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread)
00000059303FF6A8 00007ffbe644b983 [DebuggerU2MCatchHandlerFrame: 00000059303ff6a8]

tommcdon · 2023-08-02T02:03:49Z

@davmason actually is this the duplicate issue? - #86838

tommcdon · 2023-08-02T02:06:24Z

Possible workaround in the test - #86370

davmason · 2023-08-02T07:32:10Z

Yeah, the previous failure is #86838. Now that the workaround is in we shouldn't see it anymore.

There are two current failures

WASM isn't supported, we can exclude the test from WASM by adding it to the WASM group in issues.targets:

runtime/src/tests/issues.targets

Line 3102 in 63f4c6e

<ItemGroup Condition="'$(TargetArchitecture)' == 'wasm' or '$(TargetsAppleMobile)' == 'true'">
The test timed out on linux x64. Looking at the code I think the loop where random tasks are generated is suspicious. Generally I would like to see it be more intentional about what we're doing in the test. Could we change it to listen for something that generates verbose and non-verbose events (say GC with keywords=0x1) and then verify that LogAlways, Informational, and Verbose get the expected events after a GC happens?

src/tests/tracing/runtimeeventsource/NativeRuntimeLevelKeywords.cs

davmason · 2023-08-10T23:20:26Z

@n77y, it looks like you're iterating on the test so I haven't looked at your recent changes. When you would like me to take a look please let me know

nickyMcDonald · 2023-08-10T23:40:10Z

@davmason, feel free to take a look when you get a chance. I have been running into issues with even targeting one or two events. In some cases, all the listeners will pick up no events. This appears to coincide with specific builds.

My latest commit should only fail when there is some incongruency with what event levels the listeners receive. For example, the test will fail if the LogAlways listener is missing any events found by the Verbose listener, or if the Informational listener picked up any Verbose events that would also be a big no no.

nickyMcDonald · 2023-08-11T16:55:07Z

Build windows-x64 Checked NativeAOT failed with null reference.
I’ll add some logs for when disposed is called.

src/tests/tracing/runtimeeventsource/NativeRuntimeLevelKeywords.cs

davmason · 2023-08-23T06:21:30Z

src/tests/tracing/runtimeeventsource/NativeRuntimeLevelKeywords.cs

+
+Console.WriteLine($"\n{nameof(stopwatch.Elapsed.TotalSeconds)} {stopwatch.Elapsed.TotalSeconds}");
+
+WarningIfNoEventsAtLevel(informational);


No one will read the output of the tests unless there is a failure, so a warning is effectively the same as doing nothing. It seems like we should fail the test if there are no events

A few platforms are failing with no OnEventWritten()'s.

I'm going to add some logic to see if its an issue with the ConcurrentDictionary.

lateralusX · 2023-08-28T15:24:31Z

src/tests/tracing/runtimeeventsource/NativeRuntimeLevelKeywords.cs

+    }
+    GC.Collect();
+
+    if (informational.Contains("GCStart_V2") && verbose.Contains("GCAllocationTick_V4"))


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.

tommcdon · 2023-09-25T20:17:03Z

@n77y thanks for the contribution on this PR! Please let us know if you are planning on addressing the feedback in the short term. Otherwise we will plan on setting the PR status to "draft".

tommcdon · 2023-10-02T13:29:51Z

@n77y I’ve changed this PR to draft mode. Please feel free to move change the status once work resumes on it.

ghost · 2023-11-01T17:01:18Z

Draft Pull Request was automatically closed for 30 days of inactivity. Please let us know if you'd like to reopen it.

Add log level and keyword tests for NativeRuntimeEventSource

3401329

dotnet-issue-labeler bot added the area-Tracing-coreclr label Aug 1, 2023

ghost added the community-contribution Indicates that the PR has been added by a community member label Aug 1, 2023

nickyMcDonald added 2 commits August 1, 2023 22:13

Update NativeRuntimeLevelKeywords.cs

212c88d

Update NativeRuntimeLevelKeywords.cs

52367d8

nickyMcDonald added 4 commits August 3, 2023 11:46

Update issues.targets

6a973f1

Update NativeRuntimeLevelKeywords.cs

c8be0d7

Update NativeRuntimeLevelKeywords.cs

25f3b39

Update NativeRuntimeLevelKeywords.cs

0f51711

nickyMcDonald mentioned this pull request Aug 6, 2023

FIX #87983 - Enable events for LogAlways #89326

Merged

davmason reviewed Aug 8, 2023

View reviewed changes

src/tests/tracing/runtimeeventsource/NativeRuntimeLevelKeywords.cs Outdated Show resolved Hide resolved

davmason reviewed Aug 8, 2023

View reviewed changes

src/tests/tracing/runtimeeventsource/NativeRuntimeLevelKeywords.cs Outdated Show resolved Hide resolved

nickyMcDonald added 3 commits August 9, 2023 15:53

Update NativeRuntimeLevelKeywords.cs

8b4bc98

Update NativeRuntimeLevelKeywords.cs

1deffe6

Update NativeRuntimeLevelKeywords.cs

14c69e4

nickyMcDonald requested a review from davmason August 11, 2023 12:49

nickyMcDonald added 2 commits August 11, 2023 12:56

Update NativeRuntimeLevelKeywords.cs

e6c6c94

Update NativeRuntimeLevelKeywords.cs

c3dbefe

build-analysis bot mentioned this pull request Aug 11, 2023

Tracking issue for CI build timeouts #76454

Closed

davmason requested changes Aug 23, 2023

View reviewed changes

ghost added the needs-author-action An issue or pull request that requires more info or actions from the author. label Aug 23, 2023

Update NativeRuntimeLevelKeywords.cs

86bdbe1

ghost removed the needs-author-action An issue or pull request that requires more info or actions from the author. label Aug 23, 2023

This was referenced Aug 23, 2023

tracing/runtimeeventsource/nativeruntimeeventsource/nativeruntimeeventsource failing in CI #90605

Open

[8.0] [wasm] Build failure: dotnet-install: Failed to check the disk space #91025

Closed

Update NativeRuntimeLevelKeywords.cs

82b8d24

nickyMcDonald requested a review from davmason August 24, 2023 17:39

Update NativeRuntimeLevelKeywords.cs

a6ceb3c

build-analysis bot mentioned this pull request Aug 24, 2023

Microsoft.NET.HostModel.Tests failing with "No space left on device" #91039

Closed

lateralusX reviewed Aug 28, 2023

View reviewed changes

tommcdon marked this pull request as draft October 2, 2023 13:28

ghost closed this Nov 1, 2023

ghost locked as resolved and limited conversation to collaborators Dec 1, 2023

This pull request was closed.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add log level and keyword tests for NativeRuntimeEventSource #89816

Add log level and keyword tests for NativeRuntimeEventSource #89816

nickyMcDonald commented Aug 1, 2023 •

edited

Loading

tommcdon commented Aug 2, 2023

tommcdon commented Aug 2, 2023

tommcdon commented Aug 2, 2023

davmason commented Aug 2, 2023

davmason commented Aug 10, 2023

nickyMcDonald commented Aug 10, 2023

nickyMcDonald commented Aug 11, 2023

davmason Aug 23, 2023

nickyMcDonald Aug 24, 2023

nickyMcDonald Aug 24, 2023

lateralusX Aug 28, 2023 •

edited

Loading

tommcdon commented Sep 25, 2023

tommcdon commented Oct 2, 2023

ghost commented Nov 1, 2023


		Console.WriteLine($"\n{nameof(stopwatch.Elapsed.TotalSeconds)} {stopwatch.Elapsed.TotalSeconds}");

		WarningIfNoEventsAtLevel(informational);

Add log level and keyword tests for NativeRuntimeEventSource #89816

Add log level and keyword tests for NativeRuntimeEventSource #89816

Conversation

nickyMcDonald commented Aug 1, 2023 • edited Loading

tommcdon commented Aug 2, 2023

tommcdon commented Aug 2, 2023

tommcdon commented Aug 2, 2023

davmason commented Aug 2, 2023

davmason commented Aug 10, 2023

nickyMcDonald commented Aug 10, 2023

nickyMcDonald commented Aug 11, 2023

davmason Aug 23, 2023

Choose a reason for hiding this comment

nickyMcDonald Aug 24, 2023

Choose a reason for hiding this comment

nickyMcDonald Aug 24, 2023

Choose a reason for hiding this comment

lateralusX Aug 28, 2023 • edited Loading

Choose a reason for hiding this comment

tommcdon commented Sep 25, 2023

tommcdon commented Oct 2, 2023

ghost commented Nov 1, 2023

nickyMcDonald commented Aug 1, 2023 •

edited

Loading

lateralusX Aug 28, 2023 •

edited

Loading