Marc Hernandez
066d3bc7f9
x) Refactor logging endpoints to use more concise method names x) Implement implicit conversion for Value struct x) Add direct callback functionality to log events
507 lines
16 KiB
C#
507 lines
16 KiB
C#
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<T>( 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<string> blacklist;
|
|
static ImmutableHashSet<string> 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<TraceEvent> 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;
|
|
}
|
|
}
|
|
|
|
//<Event EventName="Method/JittingStarted" MethodILSize="0x00000059" MethodNamespace="NilEvent" MethodName="DebugString" MethodSignature="instance class System.String ()" ClrInstanceID="0"/>
|
|
//<Event EventName="Method/LoadVerbose" MethodStartAddress="0x00000003045736B8" MethodSize="0x000001BC" MethodToken="0x060001BB" MethodFlags="Jitted" MethodNamespace="NilEvent" MethodName="DebugString" MethodSignature="instance class System.String ()" ClrInstanceID="0" ReJITID="0x00000000" OptimizationTier="MinOptJitted"/>
|
|
|
|
//<Event EventName="Method/InliningFailed" MethodBeingCompiledNamespace="dynamicClass" MethodBeingCompiledName="InvokeStub_EventAttribute.set_Message" MethodBeingCompiledNameSignature="class System.Object (class System.Object,class System.Object,int*)" InlinerNamespace="dynamicClass" InlinerName="InvokeStub_EventAttribute.set_Message" InlinerNameSignature="class System.Object (class System.Object,class System.Object,int*)" InlineeNamespace="System.Diagnostics.Tracing.EventAttribute" InlineeName="set_Message" InlineeNameSignature="instance void (class System.String)" FailAlways="False" FailReason="uses NextCallReturnAddress intrinsic" ClrInstanceID="0"/>
|
|
|
|
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<UInt64>( "LockID" );
|
|
var objId = te.Get<UInt64>( "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<UInt64>( "LockID" );
|
|
var objId = te.Get<UInt64>( "AssociatedObjectID" );
|
|
var threadId = te.Get<Int64>( "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<int>( "LockID" );
|
|
//var objId = te.Get<IntPtr>( "AssociatedObjectID" );
|
|
//var threadId = te.Get<Int64>( "LockOwnerThreadID" );
|
|
|
|
log.info( $"Lock {{lockId}} {te.Get( "ContentionFlags" )} Duration {te.Get<double>( "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
|
|
//<Event MSec= "180.2315" PID="35297" PName="Process(35297)" TID="294046"
|
|
|
|
LogGeneric( te, logDetails );
|
|
|
|
|
|
|
|
/*
|
|
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 );
|
|
}
|
|
|
|
|
|
};
|
|
}
|
|
|
|
private static ConcurrentDictionary<string, ImmutableHashSet<string>> 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<EventPipeProvider>()
|
|
{
|
|
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 )
|
|
{
|
|
}
|
|
}
|
|
|