From a62724bf67b00c0af40d6f0b124b5848af6a7828 Mon Sep 17 00:00:00 2001 From: Marc Hernandez Date: Mon, 27 May 2024 16:47:39 -0700 Subject: [PATCH] Update logging and event handling in GC.cs and Log.cs x) Added new event handling for runtime garbage collection events x) Implemented logging endpoints for different categories x) Improved object creation handling based on type constructors --- logging/GC.cs | 171 +++++++++++++++++++++++++++++++++++-------- logging/Log.cs | 21 +++++- ser/XmlFormatter2.cs | 15 +++- 3 files changed, 170 insertions(+), 37 deletions(-) diff --git a/logging/GC.cs b/logging/GC.cs index ae5cf4f..30a40ca 100644 --- a/logging/GC.cs +++ b/logging/GC.cs @@ -1,53 +1,162 @@ using Microsoft.Diagnostics.NETCore.Client; using Microsoft.Diagnostics.Tracing; +using Microsoft.Diagnostics.Tracing.Etlx; using Microsoft.Diagnostics.Tracing.EventPipe; using Microsoft.Diagnostics.Tracing.Parsers; using System; using System.Collections.Generic; using System.Collections.Immutable; using System.Diagnostics.Tracing; +using System.Text; +using TraceKeywords = Microsoft.Diagnostics.Tracing.Parsers.ClrTraceEventParser.Keywords; + public class RuntimeGCEventsPrinter { - public static void PrintRuntimeGCEvents(int processId) - { - var providers = new List() - { - new EventPipeProvider("Microsoft-Windows-DotNETRuntime", - EventLevel.Informational, (long)ClrTraceEventParser.Keywords.Default) - }; + static ImmutableHashSet blacklist; + static ImmutableHashSet stacklist; - var client = new DiagnosticsClient(processId); - using (EventPipeSession session = client.StartEventPipeSession(providers, false)) - { - var source = new EventPipeEventSource(session.EventStream); + static RuntimeGCEventsPrinter() + { + blacklist = ImmutableHashSet.Create( + "Method/ILToNativeMap", + "GC/BulkMovedObjectRanges", + "GC/BulkSurvivingObjectRanges", + "GC/FinalizeObject", + "Type/BulkType", + "GC/SetGCHandle", + "GC/DestoryGCHandle", + "TypeLoad/Start", + "Method/R2RGetEntryPointStart", + "Method/MethodDetails", + "Method/MemoryAllocatedForJitCode" + ); + stacklist = ImmutableHashSet.Create( "{TEST_ITEM}" ); - var blacklist = ImmutableHashSet.Create( "Method/ILToNativeMap", "GC/BulkMovedObjectRanges", "GC/BulkSurvivingObjectRanges" ); + log.logEndpointForCategory( "Method/MemoryAllocatedForJitCode", log.Endpoints.File ); + log.logEndpointForCategory( "TypeLoad/Stop", log.Endpoints.File ); + log.logEndpointForCategory( "GC/BulkRootStaticVar", log.Endpoints.File ); + log.logEndpointForCategory( "GC/BulkNode", log.Endpoints.File ); + log.logEndpointForCategory( "GC/BulkRootStaticVar", log.Endpoints.File ); - var fnFilter = (TraceEvent te) => { - //Console.WriteLine(obj.ToString()); - if( blacklist.Contains( te.EventName ) ) return; + } - log.info( $"{te}", cat: "clr" ); + public static Action LogCategoryFunc( string catIn ) + { + return ( TraceEvent te ) => + { + var cat = catIn; - }; + if( blacklist.Contains( te.EventName )) return; - source.Clr.All += fnFilter; + { + var methodBeingCompiledNamespace = te.PayloadStringByName("MethodBeingCompiledNamespace") ?? ""; + if( ( methodBeingCompiledNamespace.StartsWith( "Microsoft" ) || methodBeingCompiledNamespace.StartsWith( "System" ) ) ) return; + } - source.Kernel.All += fnFilter; + { + var methodNamespace = te.PayloadStringByName("MethodNamespace") ?? ""; + if( ( methodNamespace.StartsWith( "Microsoft" ) || methodNamespace.StartsWith( "System" ) ) ) return; + } - source.Dynamic.All += fnFilter; + { + var ns = te.PayloadStringByName("TypeName") ?? ""; + if( ( ns.StartsWith( "Microsoft" ) || ns.StartsWith( "System" ) ) ) return; + } + + if( !te.EventName.StartsWith( "EventID") ) + { + //var eventData = te.EventData(); + + log.info( $"{te}", cat: te.EventName ); + + /* + if( eventData.Length > 0 ) + { + Encoding enc = new UnicodeEncoding(false, false, true); + var eventDataUtf16 = enc.GetString( eventData ); + log.debug( $"> {eventDataUtf16}" ); + } + */ + } + else + { + /* + var payloadNames = te.PayloadNames; + var channel = te.Channel; + var formattedMsg = te.FormattedMessage; + var keywords = te.Keywords; + var source = te.Source; + var dump = te.Dump(); + var dynMemberNames = te.GetDynamicMemberNames(); + var dataStart = te.DataStart; + */ + + var eventData = te.EventData(); + + //var eventDataStr = eventData.ToString(); + + Encoding enc = new UnicodeEncoding(false, false, true); + var eventDataUtf16 = enc.GetString( eventData ); + //var safeEventData = eventDataUtf16.Replace( (char)0, '\n' ); + + var arrEventData = eventDataUtf16.Split( (char)0 ); + var joinedEventData = string.Join( " | ", arrEventData ); + + //log.info( $"{te.FormattedMessage}", cat: catIn ); + log.info( $"{joinedEventData}", cat: catIn ); + } - try - { - source.Process(); - } - catch (Exception e) - { - Console.WriteLine("Error encountered while processing events"); - Console.WriteLine(e.ToString()); - } - } - } + }; + } + + + public static void PrintRuntimeGCEvents( int processId ) + { + var providers = new List() + { + new EventPipeProvider("Microsoft-Windows-DotNETRuntime", + EventLevel.Verbose, (long)( + TraceKeywords.GC | + TraceKeywords.Contention | + TraceKeywords.Debugger | + TraceKeywords.Exception | + TraceKeywords.GCAllObjectAllocation | + TraceKeywords.GCSampledObjectAllocationHigh | + TraceKeywords.GCSampledObjectAllocationLow | + TraceKeywords.Security | + TraceKeywords.Threading | + TraceKeywords.Type | + TraceKeywords.TypeDiagnostic | + TraceKeywords.WaitHandle | + TraceKeywords.All + ) ) + }; + + var client = new DiagnosticsClient( processId ); + using( EventPipeSession session = client.StartEventPipeSession( providers, false ) ) + { + var source = new EventPipeEventSource( session.EventStream ); + + + + source.Clr.All += LogCategoryFunc( "clr" ); + + source.Kernel.All += LogCategoryFunc( "kernel" ); + + source.Dynamic.All += LogCategoryFunc( "dynamic" ); + + + try + { + source.Process(); + } + catch( Exception e ) + { + Console.WriteLine( "Error encountered while processing events" ); + Console.WriteLine( e.ToString() ); + } + } + } } diff --git a/logging/Log.cs b/logging/Log.cs index f2efbe6..05a5145 100644 --- a/logging/Log.cs +++ b/logging/Log.cs @@ -13,6 +13,7 @@ using System.Security.Cryptography.X509Certificates; using lib.Net; using System.Dynamic; using System.Xml.Schema; +using Microsoft.CodeAnalysis.CSharp.Syntax; //using System.Threading.Tasks; #nullable enable @@ -179,6 +180,10 @@ static public class log static ImmutableDictionary s_shortname = ImmutableDictionary.Empty; + + + + public LogEvent( LogType logType, string msg, string path, int line, string member, string cat, string exp, object? obj ) { @@ -231,6 +236,13 @@ static public class log public delegate void Log_delegate( LogEvent evt ); + static ImmutableDictionary s_logEPforCat = ImmutableDictionary.Empty; + + + static public void logEndpointForCategory( string cat, Endpoints ep ) + { + ImmutableInterlocked.AddOrUpdate( ref s_logEPforCat, cat, ep, (k, v) => ep ); + } @@ -622,7 +634,7 @@ static public class log var truncatedCat = evt.Cat.Substring( 0, Math.Min( s_catWidth, evt.Cat.Length ) ); - var timeHdr = $"{s_timeHeader}{span.Seconds.ToString("D2")}.{span.Milliseconds.ToString("000")}"; + var timeHdr = $"{s_timeHeader}{((int)span.TotalMinutes).ToString("000")}:{span.Seconds.ToString("D2")}.{span.Milliseconds.ToString("000")}"; var msgHdr = string.Format( $"{timeHdr} | {{0,-{s_catWidth}}}{{1}}| ", truncatedCat, sym ); @@ -729,13 +741,16 @@ static public class log #region Write - if( ( s_endpoints & Endpoints.File ) == Endpoints.File ) + + var finalEndpoints = s_logEPforCat.TryGetValue( evt.Cat, out var ep ) ? ep | s_endpoints : s_endpoints; + + if( ( finalEndpoints & Endpoints.File ) == Endpoints.File ) { var line = msgFile( evt ); s_writer?.WriteLine( line ); } - if( ( s_endpoints & Endpoints.Console ) == Endpoints.Console ) + if( ( finalEndpoints & Endpoints.Console ) == Endpoints.Console ) { var line = msgPrint( evt ); setConsoleColor( evt ); diff --git a/ser/XmlFormatter2.cs b/ser/XmlFormatter2.cs index 500d27a..1805915 100644 --- a/ser/XmlFormatter2.cs +++ b/ser/XmlFormatter2.cs @@ -975,10 +975,19 @@ namespace lib try { - if( _cfg.VerboseLogging ) log.info( $"Activator.CreateInstance" ); + if( _cfg.VerboseLogging ) log.info( $"For {type.Name} check for constructors" ); - //Trying the nice way to creat objects first. - obj = Activator.CreateInstance( type ); + var cons = type.GetConstructor( Type.EmptyTypes ); + if( cons != null) + { + if( _cfg.VerboseLogging ) log.info( $"Activator.CreateInstance" ); + obj = Activator.CreateInstance( type ); + } + else + { + log.debug( $"For {type.Name} use GetUninitializedObject" ); + obj = System.Runtime.Serialization.FormatterServices.GetUninitializedObject( type ); + } if( _cfg.VerboseLogging ) log.info( $"Got obj {obj?.ToString()}" ); }