search

Maoni0 / realmon

A monitoring tool that tells you when GCs happen in a process and some characteristics about these GCs
MIT License
281 stars 25 forks source link

Only subscribe to the runtime events for the process requested by the user #24

Open MokoSan opened 2 years ago

MokoSan commented 2 years ago

To help with #23, only subscribe to GC events for the process requested by the user; we are currently subscribing to all processes' GC data, a majority of which we are not using.

Maoni0 commented 2 years ago

cool! do you have a before/after comparison by doing this? of course the diff would depend on how many other processes are firing GC events. you could have a test running that just does temporary allocations that you are not monitoring, in which case you should see a dramatic reduction in memory allocation (committed bytes should show a smaller diff - you can get the GC committed in windbg - now !eeheap -gc shows committed).

MokoSan commented 2 years ago

Conducted the following experiment with and without the fix i.e. the bits from this pull request and found that this fix does actually reduce the overall GC committed heap size.

Experiment Details

  1. Created a Console App that allocates a large list in an infinite loop.
  2. Ran GCRealTimeMon.exe -p <PID of the Console App>.
  3. Ran GCRealTimeMon.exe -p <PID of GCRealTimeMon in 2.>.
  4. Ran the following procdump command to get 3 dumps 5 seconds apart for the process in 3. : .\procdump.exe -ma <PID of 3> -s 5 -n 3
  5. Opened up WinDbg, loaded the 3 dumps and then entered !eeheap -gc and noted the GC Allocated Heap Size and GC Committed Heap Size.
  6. Repeated experiment with the fix from this PR.

NOTE: I needed the fix from #26 to get the 2nd GCRealtimeMon working since there seems to be an issue where events aren't written out on the Console due to collisions in the session name.

Data

Without Fix

1st Dump

GC Allocated Heap Size: Size: 0x5af7c8 (5961672) bytes. GC Committed Heap Size: Size: 0x5aa000 (5939200) bytes.

2nd Dump

GC Allocated Heap Size: Size: 0x5d17c8 (6100936) bytes. GC Committed Heap Size: Size: 0x5ca000 (6070272) bytes.

3rd Dump

GC Allocated Heap Size: Size: 0x5f17c8 (6232008) bytes. GC Committed Heap Size: Size: 0x5ea000 (6201344) bytes.

Observation: A monotonically sharp increase in the heap size over time.

With Fix

1st Dump

GC Allocated Heap Size: Size: 0x53c198 (5489048) bytes. GC Committed Heap Size: Size: 0x597000 (5861376) bytes.

2nd Dump

GC Allocated Heap Size: Size: 0x564198 (5652888) bytes. GC Committed Heap Size: Size: 0x597000 (5861376) bytes.

3rd Dump

GC Allocated Heap Size: Size: 0x582198 (5775768) bytes. GC Committed Heap Size: Size: 0x597000 (5861376) bytes.

Observation: A slight increase of the heap size over time that eventually tapers off.

Conclusion

I think this PR should be good to merge if the experimentation is sound. Do let me know if more data is needed.

Maoni0 commented 2 years ago

thanks! I wonder if this is actually avoiding the allocations done in stacks like what I mentioned in #23:

0e 00007ffa`b4ef8022     : 00007ffa`b4fa4ea8 00000000`00000003 00000116`c609a488 00007ffa`b4efba7d : coreclr!JIT_New+0x201 [D:\a\_work\1\s\src\coreclr\vm\jithelpers.cpp @ 2324] 
0f 00007ffa`b4ef105a     : 00000116`c603c3a8 00000116`c603bee8 00000116`c6066100 00000116`c63b1fe8 : Microsoft_Diagnostics_Tracing_TraceEvent!Microsoft.Diagnostics.Tracing.Parsers.Clr.GCPerHeapHistoryTraceData.GenData(Microsoft.Diagnostics.Tracing.Parsers.Clr.Gens)+0x6212
10 00007ffa`b4ee9194     : 00000116`c609a188 00007ffb`14453876 00000000`00000000 00000116`c5f368e0 : Microsoft_Diagnostics_Tracing_TraceEvent!Microsoft.Diagnostics.Tracing.Analysis.GC.GCStats.ProcessPerHeapHistory(Microsoft.Diagnostics.Tracing.Analysis.TraceLoadedDotNetRuntime, Microsoft.Diagnostics.Tracing.Parsers.Clr.GCPerHeapHistoryTraceData)+0x27a
11 00007ffa`b4ef73d9     : 00000116`e81d1740 00000015`1ed7d860 00000116`e81d1f58 00000000`00000238 : Microsoft_Diagnostics_Tracing_TraceEvent!Microsoft.Diagnostics.Tracing.TraceEventDispatcher.DoDispatch(Microsoft.Diagnostics.Tracing.TraceEvent)+0x74
12 00007ffa`b4ee8ce2     : 00000116`e81d1f20 00000015`1ed7d969 00000116`e81b80e0 00000000`00000010 : Microsoft_Diagnostics_Tracing_TraceEvent!Microsoft.Diagnostics.Tracing.ETWTraceEventSource.RawDispatch(EVENT_RECORD*)+0xe6c9
13 00007ffb`4ac337fb     : 00000116`e81d1f20 00000015`1ed7d969 00000116`00000238 00000116`e828c6d0 : System_Console!ILStubClass.IL_STUB_ReversePInvoke(Int64)+0x42

this is avoid whatever allocations we are doing in runtime.GCEnd += delegate (TraceProcess p, TraceGC gc) but my guess is it's not avoiding the allocation above which comes from processing the GCPerHeapHistory event (ie Microsoft.Diagnostics.Tracing.Parsers.Clr.GCPerHeapHistoryTraceData). but then again those allocations should be very temporary. you can verify if it's doing those allocations by setting a bp on kernelbase!VirtualAlloc* during steady state.