Description
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()