search

dotnet / diagnostics

This repository contains the source code for various .NET Core runtime diagnostic tools and documents.
MIT License
1.18k stars 355 forks source link

Reenable EventPIpe.UnitTests GCCollect_ProducesVerboseEvents test #3143

Open mikem8361 opened 2 years ago

mikem8361 commented 2 years ago

Not sure – it’s interesting that GCCreateSegment events are still fired but the free ones are not symmetrical. As you say – it’s more of what the purpose was for the event. If they save them and match them to check for memory freed, that’s a bit of a break if things get recycled. Is there any case where regions get deallocated prior to the end of the process’s life? Like shrinking working set or such? I expect to see a similar even in such a scenario. Also, maybe @Brian Robbins has a different perspective of how the event gets used. I took a quick look and I don’t see it being of particular importance in Perfview, so I am not sure what it’s intended usage was.

From @cshung:

In segments, when we call gc_heap::release_segment, we call virtual_free, so that the reserved address space is returned to the OS.

In regions, when we call gc_heap::return_free_region, all that does is that the region is returned back to a free list of regions so that they can be allocated again, we do not return the reserved address space to the OS (and currently, we aren’t even decommitting them)

For regions, we simply never release the address space back to the OS.

What do we use that event for? Firing an event at the point of return free region is not difficult, but it might not be the right thing to do, especially so if event listeners are using them to account for reserved memory.

Adding @CLR GC Core – I see that this was happening when release_segment was called – that no longer happens with regions GC. The ones where you say this passes is where GC Regions is not enabled. I don’t see any events that get fired in the regions equivalent - return_free_region. Maybe they know better there.

This is on Windows X64. It also fails on Linux x64/WSL. It passes on Windows x86 and MacOS x64.

I changed this test to run on net7.0 and it started failing. The test isn’t getting any EventPipeEventSource.clr.GCFreeSegment callbacks on net7.0 but does on 6 and 3.1. Does anybody know why? Is this a bug in the runtime?

Here is where the test adds the callback: https://github.com/mikem8361/diagnostics/blob/fe19551047ad9890edb706812ecba3faa6e6f6c5/src/tests/eventpipe/GCEvents.cs#L213

Test run for C:\ssd\diagnostics\artifacts\bin\EventPipe.UnitTests\Debug\net7.0\EventPipe.UnitTests.dll (.NETCoreApp,Version=v7.0)
Microsoft (R) Test Execution Command Line Tool Version 17.3.0-preview-20220622-01 (x64)
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
A total of 1 test files matched the specified pattern.
C:\ssd\diagnostics\artifacts\bin\EventPipe.UnitTests\Debug\net7.0\EventPipe.UnitTests.dll
[xUnit.net 00:00:00.00] xUnit.net VSTest Adapter v2.4.3+1b45f5407b (64-bit .NET 7.0.0-preview.5.22301.12)
[xUnit.net 00:00:02.24]   Discovering: EventPipe.UnitTests
[xUnit.net 00:00:02.26]   Discovered:  EventPipe.UnitTests
[xUnit.net 00:00:02.27]   Starting:    EventPipe.UnitTests
[xUnit.net 00:00:05.64]     EventPipe.UnitTests.GCEventsValidation.GCEventsTests.GCCollect_ProducesVerboseEvents [FAIL]
[xUnit.net 00:00:05.64]       Microsoft.DotNet.RemoteExecutor.RemoteExecutionException : Remote process failed with an unhandled exception.
[xUnit.net 00:00:05.65]       Stack Trace:
[xUnit.net 00:00:05.65]
[xUnit.net 00:00:05.65]         Child exception:
[xUnit.net 00:00:05.65]           Xunit.Sdk.EqualException: Assert.Equal() Failure
[xUnit.net 00:00:05.65]         Expected: 100
[xUnit.net 00:00:05.65]         Actual:   -1
[xUnit.net 00:00:05.65]         C:\ssd\diagnostics\src\tests\eventpipe\GCEvents.cs(243,0): at EventPipe.UnitTests.GCEventsValidation.GCEventsTests.<>c.<GCCollect_ProducesVerboseEvents>b__4_0()
[xUnit.net 00:00:05.65]            at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
[xUnit.net 00:00:05.65]            at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr)
[xUnit.net 00:00:05.65]
[xUnit.net 00:00:05.65]         Child process:
[xUnit.net 00:00:05.65]           EventPipe.UnitTests, Version=6.0.6.32301, Culture=neutral, PublicKeyToken=31bf3856ad364e35 EventPipe.UnitTests.GCEventsValidation.GCEventsTests+<>c Void <GCCollect_ProducesVerboseEvents>b__4_0()
[xUnit.net 00:00:05.65]
[xUnit.net 00:00:05.65]
[xUnit.net 00:00:05.65]       Output:
[xUnit.net 00:00:05.65]           0.0s: ==TEST STARTING==
[xUnit.net 00:00:05.65]           0.0s: Started sending sentinel events...
[xUnit.net 00:00:05.65]           0.0s: Connecting to EventPipe...
[xUnit.net 00:00:05.65]           0.0s: Creating EventPipeEventSource...
[xUnit.net 00:00:05.65]           0.0s: EventPipeEventSource created
[xUnit.net 00:00:05.65]           0.0s: Dynamic.All callback registered
[xUnit.net 00:00:05.65]           0.0s: Running optional trace validator
[xUnit.net 00:00:05.65]           0.1s: Finished running optional trace validator
[xUnit.net 00:00:05.65]           0.1s: Starting stream processing...
[xUnit.net 00:00:05.65]           0.2s: Saw new provider 'Microsoft-Windows-DotNETRuntime'
[xUnit.net 00:00:05.65]           0.2s: Saw new provider 'Microsoft-DotNETCore-SampleProfiler'
[xUnit.net 00:00:05.65]           0.2s: Saw sentinel event
[xUnit.net 00:00:05.65]           0.2s: Stopped sending sentinel events
[xUnit.net 00:00:05.65]           0.2s: Starting event generating action...
[xUnit.net 00:00:05.65]           1.9s: Stopping event generating action
[xUnit.net 00:00:05.65]           1.9s: Sending StopTracing command...
[xUnit.net 00:00:05.65]           2.0s: Saw new provider 'Microsoft-DotNETCore-EventPipe'
[xUnit.net 00:00:05.65]           2.0s: Saw new provider 'Microsoft-Windows-DotNETRuntimeRundown'
[xUnit.net 00:00:05.65]           2.0s: Finished StopTracing command
[xUnit.net 00:00:05.65]           2.0s: Stopping stream processing
[xUnit.net 00:00:05.65]           2.0s: Dropped 0 events
[xUnit.net 00:00:05.65]           2.0s: Reader task finished
[xUnit.net 00:00:05.65]           2.0s: Dropped 0 events
[xUnit.net 00:00:05.65]           2.0s: Task stats: isFaulted: False, Exception == null: True
[xUnit.net 00:00:05.65]           2.0s: Validating optional callback...
[xUnit.net 00:00:05.65]           2.0s: Event counts validation
[xUnit.net 00:00:05.65]           2.0s: GCCreateSegmentEvents: 7
[xUnit.net 00:00:05.65]           2.0s: GCFreeSegmentEvents: 0
[xUnit.net 00:00:05.65]           2.0s: GCSegmentResult: False
[xUnit.net 00:00:05.65]           2.0s: GCAllocationTickEvents: 40
[xUnit.net 00:00:05.65]           2.0s: GCAllocationTickResult: True
[xUnit.net 00:00:05.65]           2.0s: GCCollectResults: False
[xUnit.net 00:00:05.65]           2.0s: ==TEST FINISHED: FAILED!==
[xUnit.net 00:00:05.65]
[xUnit.net 00:00:05.65]   Finished:    EventPipe.UnitTests
  Failed EventPipe.UnitTests.GCEventsValidation.GCEventsTests.GCCollect_ProducesVerboseEvents [3 s]
  Error Message:
   Microsoft.DotNet.RemoteExecutor.RemoteExecutionException : Remote process failed with an unhandled exception.
  Stack Trace:

Child exception:
  Xunit.Sdk.EqualException: Assert.Equal() Failure
Expected: 100
Actual:   -1
   at EventPipe.UnitTests.GCEventsValidation.GCEventsTests.<>c.<GCCollect_ProducesVerboseEvents>b__4_0() in C:\ssd\diagnostics\src\tests\eventpipe\GCEvents.cs:line 243
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr)

Child process:
  EventPipe.UnitTests, Version=6.0.6.32301, Culture=neutral, PublicKeyToken=31bf3856ad364e35 EventPipe.UnitTests.GCEventsValidation.GCEventsTests+<>c Void <GCCollect_ProducesVerboseEvents>b__4_0()
mikem8361 commented 2 years ago

And part of .EventLogsPipelineUnitTests.TestLogsAllCategoriesDefaultLevelFallback line 106.

mdh1418 commented 2 weeks ago

From discussions with @cshung and @brianrob, we think it is better to restrict GCFreeSegment events to only pertain to the old GC, when it actually freed segments of address spaces rather than warping the new GC's instances of decommitting regions to correlate a GCFreeSegment event.

Given that PerfView does not use GCFreeSegment/GCCreateSegment events coupled with the fact that a new .NET 8 CommittedUsage event shows how much memory the GC committed with a breakdown of what exactly the memory is used for, there seems to be no need for GCFreeSegment/GCCreateSegment events, and we should not expect them anymore during a GC in .NET 7+

https://github.com/dotnet/diagnostics/pull/4906 looks to update the tests to reflect our new expectations.