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.

Sign up for GitHub

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

Jump to bottom

Reenable EventPIpe.UnitTests GCCollect_ProducesVerboseEvents test #3143

Open
mikem8361 opened this issue Jun 24, 2022 · 2 comments · May be fixed by #4906
Open

Reenable EventPIpe.UnitTests GCCollect_ProducesVerboseEvents test #3143

mikem8361 opened this issue Jun 24, 2022 · 2 comments · May be fixed by #4906
Labels
testing Test work item
Milestone
Future

Comments

@mikem8361
Copy link
Member

mikem8361 commented Jun 24, 2022 •
edited by cshung
Loading

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 mikem8361 added the testing Test work item label Jun 24, 2022
@mikem8361 mikem8361 added this to the 7.0.0 milestone Jun 24, 2022
@davmason davmason assigned davmason and unassigned davmason Jul 14, 2022
@davmason davmason modified the milestones: 7.0.0, Future Jul 16, 2022
@mikem8361
Copy link
Member Author

And part of .EventLogsPipelineUnitTests.TestLogsAllCategoriesDefaultLevelFallback line 106.

@mdh1418 mdh1418 linked a pull request Sep 4, 2024 that will close this issue
Open
@mdh1418
Copy link
Member

mdh1418 commented Sep 4, 2024

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+

#4906 looks to update the tests to reflect our new expectations.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
testing Test work item
Projects
None yet
Milestone
Future
Development

Successfully merging a pull request may close this issue.

[Tests] Update GC SegmentEvents validation mdh1418/diagnostics
3 participants
@mikem8361 @davmason @mdh1418