using lib; 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 Microsoft.Diagnostics.Tracing.Parsers.Clr; using Microsoft.Diagnostics.Tracing.Parsers.Kernel; using Microsoft.Diagnostics.Tracing.Session; using System; using System.Collections.Concurrent; using System.Collections.Generic; using System.Collections.Immutable; using System.Diagnostics; using System.Diagnostics.Tracing; using System.IO; using System.Linq; using System.Runtime.InteropServices; using System.Runtime.Remoting; using System.Text; using System.Threading; using System.Threading.Tasks; using System.Xml; using TraceKeywords = Microsoft.Diagnostics.Tracing.Parsers.ClrTraceEventParser.Keywords; public static class LogGCExt { public static string MethodInfo( TraceEvent te, string prefix = "Method" ) { return $"{te.PayloadStringByName($"{prefix}Namespace")}.{te.PayloadStringByName($"{prefix}Name")}{te.PayloadStringByName($"{prefix}Signature")}"; } public static string Get( this TraceEvent te, string name, string def = "" ) => te.PayloadStringByName( name ) ?? def; public static T Get( this TraceEvent te, string name, T def = default ) { var index = te.PayloadIndex( name ); if( index <= 0 ) return default; var value = te.PayloadValue( index ); if( value.GetType() != typeof(T) ) { log.warn( $"In {te.ID} Payload {name} is type {value.GetType().FriendlyName()} not {typeof(T).FriendlyName()}" ); return default; } return (T)value; } } public class LogGC { static ImmutableHashSet blacklist; static ImmutableHashSet stacklist; static LogGC() { blacklist = ImmutableHashSet.Create( "FAKE_TEST", "GC/BulkMovedObjectRanges", /* "GC/BulkSurvivingObjectRanges", "GC/BulkRootStaticVar", "GC/BulkNode", "GC/BulkEdge", "GC/BulkRootEdge", "GC/FinalizeObject", "GC/SetGCHandle", "GC/DestoryGCHandle", "GC/MarkWithType", "GC/SuspendEEStart", "GC/SuspendEEStop", "GC/RestartEEStart", "GC/RestartEEStop", "GC/FinalizersStart", // "GC/FinalizersStop", //Keep this one since it has details "GC/GenerationRange", "GC/FitBucketInfo", "TieredCompilation/BackgroundJitStart", "Type/BulkType", "TypeLoad/Start", "Method/R2RGetEntryPointStart", "Method/MethodDetails", "Method/MemoryAllocatedForJitCode", "Method/JittingStarted", "Method/ILToNativeMap", "ThreadPoolWorkerThread/Wait", "ILStub/StubGenerated" */ "FAKE_END_IS_NOTHING" ); stacklist = ImmutableHashSet.Create( "{TEST_ITEM}" ); log.endpointForCat( "Method/MemoryAllocatedForJitCode", log.Endpoints.File ); log.endpointForCat( "TypeLoad/Stop", log.Endpoints.File ); log.endpointForCat( "GC/BulkRootStaticVar", log.Endpoints.File ); log.endpointForCat( "GC/BulkNode", log.Endpoints.File ); log.endpointForCat( "GC/BulkRootStaticVar", log.Endpoints.File ); } static public void RegisterObjectId( object obj ) { /* var gchWeak = GCHandle.Alloc( obj, GCHandleType.Weak ); var gchNRML = GCHandle.Alloc( obj, GCHandleType.Normal ); var intPtrWeak = GCHandle.ToIntPtr( gchWeak ); var intPtrNRML = GCHandle.ToIntPtr( gchNRML ); //var intPtr = Marshal.GetIUnknownForObject( obj ); var intPtr = 0; //gchNRML.AddrOfPinnedObject(); //Marshal.GetTypedObjectForIUnknown() // 0x00000003400111C0 // 0000000000000000 log.info( $"Log ObjectIDs: 0x{intPtrNRML.ToString("X"):0000000000000000} 0x{intPtrWeak.ToString("X"):0000000000000000}" ); //*/ } public static Action LogCategoryFunc( string catIn ) { return ( TraceEvent te ) => { var cat = catIn; if( blacklist.Contains( te.EventName )) return; { var methodBeingCompiledNamespace = te.Get("MethodBeingCompiledNamespace"); if( ( methodBeingCompiledNamespace.StartsWith( "Microsoft" ) || methodBeingCompiledNamespace.StartsWith( "System" ) ) ) return; } { var methodNamespace = te.PayloadStringByName("MethodNamespace") ?? ""; if( ( methodNamespace.StartsWith( "Microsoft" ) || methodNamespace.StartsWith( "System" ) ) ) return; } { var ns = te.PayloadStringByName("TypeName") ?? ""; if( ( ns.StartsWith( "Microsoft" ) || ns.StartsWith( "System" ) ) ) return; } { var ns = te.PayloadStringByName("TypeLoad/Stop") ?? ""; if( ns.StartsWith( "Godot" ) ) return; } { var payloadIndex = te.PayloadIndex( "count" ); if( payloadIndex > 0 ) { var count = (int)te.PayloadValue( payloadIndex ); if( count > 16 ) return; } } // // // if( !te.EventName.StartsWith( "EventID") ) { var logDetails = ""; // Custom event displays if( te.EventName == "Method/LoadVerbose" ) { var optTier = te.Get( "OptimizationTier" ); var methodNamespace = te.Get( "MethodNamespace" ); if( optTier == "MinOptJitted" ) return; if( methodNamespace.StartsWith( "FastSerialization" )) return; log.info( $"{optTier} {LogGCExt.MethodInfo( te )}", cat: te.EventName ); return; //logDetails = "| Details: "; } else if( te.EventName.StartsWith( "Method/Inlining" ) ) { var methodNamespace = te.Get( "MethodBeingCompiledNamespace" ); if( methodNamespace.StartsWith( "FastSerialization" )) return; log.info( $"Inlining {te.Get( "FailReason" )} {te.Get( "OptimizationTier" )} {LogGCExt.MethodInfo( te, "MethodBeingCompiled" )}", cat: te.EventName ); return; //logDetails = "| Details: "; } else if( te.EventName == "Type/BulkType" ) { var val = te.ToString(); XmlDocument doc = new(); var stream = new MemoryStream(); var writer = new StreamWriter(stream); writer.Write( val ); writer.Flush(); stream.Position = 0; doc.Load( stream ); var root = doc.DocumentElement; XmlNodeList children = root.ChildNodes; foreach( var child in children ) { var node = child as XmlElement; log.info( $"Child: {node.Name}" ); } return; } else if( te.EventName == "TypeLoad/Stop" ) { /* var typeName = te.PayloadStringByName( "TypeName" ); if( typeName.StartsWith( "Godot." ) ) return; log.info( $"{typeName} Level: {te.PayloadStringByName( "LoadLevel" )}", cat: te.EventName ); //*/ return; //logDetails = "| Details: "; } else if( te.EventName.StartsWith( "Method/R2RGetEntryPoint" ) ) { log.info( $"{LogGCExt.MethodInfo( te )} Entry: {te.PayloadStringByName( "EntryPoint" )}", cat: te.EventName ); return; //logDetails = "| Details: "; } else if( te.EventName.StartsWith( "Contention/LockCreated" ) ) { // "Contention/Start" AssociatedObjectID // System.Runtime.InteropServices.GCHandle.FromIntPtr( var lockId = te.Get( "LockID" ); var objId = te.Get( "AssociatedObjectID" ); var testObj = Marshal.GetIUnknownForObject(objId); var intPtrStr = te.PayloadStringByName( "AssociatedObjectID" ).Substring( 2 ); try { //var intPtr = Convert.ToUInt64( intPtrStr, 16 ); //var gch = System.Runtime.InteropServices.GCHandle.FromIntPtr( intPtr ); var gch = new GCHandle(); //* var allocated = gch.IsAllocated; var obj = gch.Target; log.info( $"Lock {lockId} Create {objId.ToString("X")} {obj?.GetType()?.Name} {obj}", cat: te.EventName ); //*/ } catch( Exception ex ) { log.info( $"Lock {lockId} Create 0x{intPtrStr} (Could not get object) [{ex.Message}]", cat: te.EventName ); } LogGeneric( te, "| Raw: " ); return; //logDetails = "| Details: "; } else if( te.EventName.StartsWith( "Contention/Start" ) ) { // EventName="Contention/Start" ContentionFlags="Managed" LockID="0x000000011D015CB8" AssociatedObjectID="0x00000003504554C0" LockOwnerThreadID="0" // EventName="Contention/Stop" ContentionFlags="Managed" DurationNs="26000" var lockId = te.Get( "LockID" ); var objId = te.Get( "AssociatedObjectID" ); var threadId = te.Get( "LockOwnerThreadID" ); log.info( $"Lock {lockId} {te.Get( "ContentionFlags" )} in thread {threadId} on obj 0x{objId.ToString("X")} ", cat: te.EventName ); LogGeneric( te, "| Raw: " ); } else if( te.EventName.StartsWith( "Contention/Stop" ) ) { //var lockId = te.Get( "LockID" ); //var objId = te.Get( "AssociatedObjectID" ); //var threadId = te.Get( "LockOwnerThreadID" ); log.info( $"Lock {{lockId}} {te.Get( "ContentionFlags" )} Duration {te.Get( "DurationNs" )}ns", cat: te.EventName ); LogGeneric( te, "| Raw: " ); } else if( te.EventName.StartsWith( "AssemblyLoader/" ) || te.EventName.StartsWith( "Loader/" ) ) { //AssemblyLoader/Start AssemblyName AssemblyLoadContext RequestingAssemblyLoadContext AssemblyPath RequestingAssembly //AssemblyLoader/Stop AssemblyName AssemblyLoadContext RequestingAssemblyLoadContext AssemblyPath RequestingAssembly Success ResultAssemblyName ResultAssemblyPath Cached //Loader/AssemblyLoad AssemblyID AppDomainID AssemblyFlags FullyQualifiedAssemblyName BindingID //AssemblyLoader/ResolutionAttempted // AssemblyName AssemblyLoadContext Result ResultAssemblyName ResultAssemblyPath Stage ErrorMessage //Loader/ModuleLoad ModuleID AssemblyID ModuleFlags ModuleILPath ModuleNativePath ManagedPdbSignature ManagedPdbAge ManagedPdbBuildPath //Loader/DomainModuleLoad ModuleID AssemblyID ModuleFlags ModuleILPath ModuleNativePath AppDomainID //AssemblyLoader/KnownPathProbed FilePath Source Result var appDomainId = te.Get( "AppDomainID" ); var asId = te.Get( "AssemblyID" ); var asName = te.Get( "AssemblyName" ); var asPath = te.Get( "AssemblyPath" ); var asLC = te.Get( "AssemblyLoadContext" ); var reqAs = te.Get( "RequestingAssembly" ); var reqAsLC = te.Get( "RequestingAssemblyLoadContext" ); var reqAsName = te.Get( "ResultAssemblyName" ); var reqAsPath = te.Get( "ResultAssemblyPath" ); var success = te.Get( "Success" ); var cached = te.Get( "Cached" ); var errMsg = te.Get( "ErrorMessage" ); var stage = te.Get( "Stage" ); var result = te.Get( "Result" ); var source = te.Get( "Source" ); var modId = te.Get( "ModuleID" ); var modFlags = te.Get( "ModuleFlags" ); var modILPath = te.Get( "ModuleILPath" ); var modNativePath= te.Get( "ModuleNativePath" ); var manBuildPath= te.Get( "ManagedPdbBuildPath" ); var fqaName = te.Get( "FullyQualifiedAssemblyName" ); var bindingId = te.Get( "BindingID" ); } //76 CHARACTERS // 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 ); } }; } private static ConcurrentDictionary> s_validKeywords = new(); private static void LogGeneric( TraceEvent te, string logDetails ) { var teStr = te.ToString().Replace( "ClrInstanceID=\"0\"", "" ); /* */ var startIndex = teStr.IndexOf( "EventName" ); //log.debug( $"{logDetails} {startIndex} {teStr}", cat: te.EventName ); var teStrSlice = teStr.AsSpan( startIndex, teStr.Length - ( startIndex + 1 + 1 ) ); log.debug( $"{logDetails}{teStrSlice}", cat: te.EventName ); /* try { TraceCallStack? callstack = te.CallStack(); //if( callstack != null) log.trace( $"| Callstack: {callstack?.ToString()}" ); if( callstack != null ) { log.trace( $"| Callstack:" ); log.trace( $"| {callstack.Depth}" ); log.trace( $"| {callstack.CodeAddress}" ); } } catch( Exception ex ) { log.debug( $"Caught {ex.Message} while getting the callstack" ); } //*/ } 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.GCAllocationTick += OnAllocTick; //source.Clr.All += LogCategoryFunc( "clr" ); //source.Kernel.All += LogCategoryFunc( "kernel" ); // Doesnt seem to be too interesting. //source.Dynamic.All += LogCategoryFunc( "dynamic" ); try { source.Process(); } catch( Exception e ) { Console.WriteLine( "Error encountered while processing events" ); Console.WriteLine( e.ToString() ); } } } private static void OnAllocTick( GCAllocationTickTraceData data ) { } }