517 lines
16 KiB
C#
517 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 )
|
|
{
|
|
}
|
|
}
|
|
|