Update logging events and improve log details display

x) Add new logging events for GC and ThreadPoolWorkerThread
x) Implement method to extract method information from TraceEvent
x) Enhance log details display for specific event types
x) Improve time header format in log messages
x) Refactor verbose logging messages to include type friendly names
This commit is contained in:
Marc Hernandez 2024-06-02 16:26:11 -07:00
parent 7f9b210bbd
commit 1fd02d1460
4 changed files with 140 additions and 20 deletions

View File

@ -43,6 +43,45 @@ namespace lib
public static class Util public static class Util
{ {
/*
public static string StringJoin( string separator, IEnumerable<object> collectionToConvert )
{
return String.Join(separator, collectionToConvert.Select(o => o.ToString()));
}
public static string FriendlyName(this Type type)
{
if (type.IsGenericType)
{
var namePrefix = type.Name.Split(new [] {'`'}, StringSplitOptions.RemoveEmptyEntries)[0];
var genericParameters = StringJoin( ", ", type.GetGenericArguments() );
return namePrefix + "<" + genericParameters + ">";
}
return type.Name;
}
*/
public static string ToString<T>(this IEnumerable<T> collectionToConvert, string separator)
{
return String.Join(separator, collectionToConvert.Select(o => o.ToString()));
}
public static string FriendlyName(this Type type)
{
if (type.IsGenericType)
{
var namePrefix = type.Name.Split(new [] {'`'}, StringSplitOptions.RemoveEmptyEntries)[0];
var genericParameters = type.GetGenericArguments().ToString( ", ") ;
return namePrefix + "<" + genericParameters + ">";
}
return type.Name;
}
/* /*
#if XENKO_PLATFORM_UWP #if XENKO_PLATFORM_UWP
public static unsafe void CopyMemory(IntPtr dest, IntPtr src, int sizeInBytesToCopy) public static unsafe void CopyMemory(IntPtr dest, IntPtr src, int sizeInBytesToCopy)

View File

@ -29,7 +29,15 @@ public class RuntimeGCEventsPrinter
"TypeLoad/Start", "TypeLoad/Start",
"Method/R2RGetEntryPointStart", "Method/R2RGetEntryPointStart",
"Method/MethodDetails", "Method/MethodDetails",
"Method/MemoryAllocatedForJitCode" "Method/MemoryAllocatedForJitCode",
"Method/JittingStarted",
"GC/BulkRootStaticVar",
"GC/BulkNode",
"GC/BulkEdge",
"GC/BulkRootEdge",
"ThreadPoolWorkerThread/Wait",
"ILStub/StubGenerated"
); );
stacklist = ImmutableHashSet.Create( "{TEST_ITEM}" ); stacklist = ImmutableHashSet.Create( "{TEST_ITEM}" );
@ -41,6 +49,11 @@ public class RuntimeGCEventsPrinter
} }
public static string MethodInfo( TraceEvent te, string prefix = "Method" )
{
return $"{te.PayloadStringByName($"{prefix}Namespace")}.{te.PayloadStringByName($"{prefix}Name")}{te.PayloadStringByName($"{prefix}Signature")}";
}
public static Action<TraceEvent> LogCategoryFunc( string catIn ) public static Action<TraceEvent> LogCategoryFunc( string catIn )
{ {
return ( TraceEvent te ) => return ( TraceEvent te ) =>
@ -64,11 +77,69 @@ public class RuntimeGCEventsPrinter
if( ( ns.StartsWith( "Microsoft" ) || ns.StartsWith( "System" ) ) ) return; 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") ) if( !te.EventName.StartsWith( "EventID") )
{ {
//var eventData = te.EventData(); var logDetails = "";
// Custom event displays
if( te.EventName == "Method/LoadVerbose" )
{
log.info( $"{te.PayloadStringByName("OptimizationTier")} {MethodInfo(te)}", cat: te.EventName );
return;
//logDetails = "| Details: ";
}
else if( te.EventName.StartsWith( "Method/Inlining" ) )
{
log.info( $"Inlining {te.PayloadStringByName("FailReason")} {te.PayloadStringByName("OptimizationTier")} {MethodInfo(te, "MethodBeingCompiled")}", cat: te.EventName );
return;
//logDetails = "| Details: ";
}
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( $"{MethodInfo(te)} Entry: {te.PayloadStringByName("EntryPoint")}", cat: te.EventName );
return;
//logDetails = "| Details: ";
}
//76 CHARACTERS
//<Event MSec= "180.2315" PID="35297" PName="Process(35297)" TID="294046"
var teStr = te.ToString().Replace("ClrInstanceID=\"0\"", "" );
var teStrSlice = teStr.AsSpan( 74, teStr.Length - (74 + 1 + 1) );
log.debug( $"{logDetails}{teStrSlice}", cat: te.EventName );
log.info( $"{te}", cat: te.EventName );
/* /*
if( eventData.Length > 0 ) if( eventData.Length > 0 )
@ -145,7 +216,8 @@ public class RuntimeGCEventsPrinter
source.Kernel.All += LogCategoryFunc( "kernel" ); source.Kernel.All += LogCategoryFunc( "kernel" );
source.Dynamic.All += LogCategoryFunc( "dynamic" ); // Doesnt seem to be too interesting.
//source.Dynamic.All += LogCategoryFunc( "dynamic" );
try try

View File

@ -79,7 +79,7 @@ static public class log
static log() static log()
{ {
/* //*
{ {
var start = new ThreadStart( StartGCWatcher ); var start = new ThreadStart( StartGCWatcher );
@ -657,7 +657,9 @@ static public class log
var truncatedCat = evt.Cat.Substring( 0, Math.Min( s_catWidth, evt.Cat.Length ) ); var truncatedCat = evt.Cat.Substring( 0, Math.Min( s_catWidth, evt.Cat.Length ) );
var timeHdr = $"{evt.Time.Year}-{evt.Time.Month.ToString("00")}-{evt.Time.Day.ToString("00")} {evt.Time.Hour.ToString("00")}:{evt.Time.Minute.ToString("00")}:{evt.Time.Second.ToString("00")}.{evt.Time.Millisecond.ToString("000")}{evt.Time.Microsecond.ToString("000")}"; //Dont really need the year-month-day frankly.
//var timeHdr = $"{evt.Time.Year}-{evt.Time.Month.ToString("00")}-{evt.Time.Day.ToString("00")} {evt.Time.Hour.ToString("00")}:{evt.Time.Minute.ToString("00")}:{evt.Time.Second.ToString("00")}.{evt.Time.Millisecond.ToString("000")}{evt.Time.Microsecond.ToString("000")}";
var timeHdr = $"{evt.Time.Hour.ToString("00")}:{evt.Time.Minute.ToString("00")}:{evt.Time.Second.ToString("00")}.{evt.Time.Millisecond.ToString("000")}{evt.Time.Microsecond.ToString("000")}";
var msgHdr = string.Format( $"{timeHdr} | {{0,-{s_catWidth}}}{{1}}| ", truncatedCat, sym ); var msgHdr = string.Format( $"{timeHdr} | {{0,-{s_catWidth}}}{{1}}| ", truncatedCat, sym );

View File

@ -147,6 +147,13 @@ namespace lib
public class XmlFormatter2 : IFormatter public class XmlFormatter2 : IFormatter
{ {
public StreamingContext Context { get; set; } public StreamingContext Context { get; set; }
private XmlFormatter2Cfg _cfg = new(); private XmlFormatter2Cfg _cfg = new();
@ -302,7 +309,7 @@ namespace lib
{ {
TypeCode typeCode = Type.GetTypeCode( type ); TypeCode typeCode = Type.GetTypeCode( type );
if( _cfg.VerboseLogging ) log.info( $"{type.Name}.{name} {existing} {mi?.Name}" ); if( _cfg.VerboseLogging ) log.info( $"{type.FriendlyName()}.{name} {existing} {mi?.Name}" );
if( typeCode != TypeCode.Object ) if( typeCode != TypeCode.Object )
{ {
@ -337,7 +344,7 @@ namespace lib
} }
catch( Exception ex ) catch( Exception ex )
{ {
log.warn( $"Caught exception fn {mi?.Name} type {type?.Name} of {ex.Message}" ); log.warn( $"Caught exception fn {mi?.Name} type {type?.FriendlyName()} of {ex.Message}" );
} }
return existing; return existing;
@ -709,7 +716,7 @@ namespace lib
int refInt = refString.Length > 0 ? Convert.ToInt32( refString ) : -1; int refInt = refString.Length > 0 ? Convert.ToInt32( refString ) : -1;
if( _cfg.VerboseLogging ) log.info( $"{finalType?.Name}({type?.Name}) refInt {refInt} exitingObj = {obj?.ToString()}" ); if( _cfg.VerboseLogging ) log.info( $"{finalType?.FriendlyName()}({type?.FriendlyName()}) refInt {refInt} exitingObj = {obj?.ToString()}" );
obj = createObject( elem, finalType, refInt, obj ); obj = createObject( elem, finalType, refInt, obj );
@ -754,7 +761,7 @@ namespace lib
typeElem = typeof( KeyValuePair<,> ).MakeGenericType( type.GenericTypeArguments ); typeElem = typeof( KeyValuePair<,> ).MakeGenericType( type.GenericTypeArguments );
} }
if( _cfg.VerboseLogging ) log.info( $"DserCol {type.GetType().Name} {typeElem.Name} into reflT {mi.ReflectedType.Name} declT {mi.DeclaringType.Name} {mi.Name}" ); if( _cfg.VerboseLogging ) log.info( $"DserCol {type.GetType().FriendlyName()} {typeElem.Name} into reflT {mi.ReflectedType.FriendlyName()} declT {mi.DeclaringType.FriendlyName()} {mi.Name}" );
string refString = elem.GetAttribute( "ref" ); string refString = elem.GetAttribute( "ref" );
int refInt = refString.Length > 0 ? Convert.ToInt32( refString ) : -1; int refInt = refString.Length > 0 ? Convert.ToInt32( refString ) : -1;
@ -799,7 +806,7 @@ namespace lib
var typeGen = Type.MakeGenericSignatureType( type ); var typeGen = Type.MakeGenericSignatureType( type );
if( _cfg.VerboseLogging ) log.info( $"TypeGen: {typeGen.Name}" ); if( _cfg.VerboseLogging ) log.info( $"TypeGen: {typeGen.FriendlyName()}" );
if( type == typeof( ImmutableArray<> ).MakeGenericType( typeElem ) ) if( type == typeof( ImmutableArray<> ).MakeGenericType( typeElem ) )
{ {
@ -975,7 +982,7 @@ namespace lib
try try
{ {
if( _cfg.VerboseLogging ) log.info( $"For {type.Name} check for constructors" ); if( _cfg.VerboseLogging ) log.info( $"For {type.FriendlyName()} check for constructors" );
var cons = type.GetConstructor( Type.EmptyTypes ); var cons = type.GetConstructor( Type.EmptyTypes );
if( cons != null) if( cons != null)
@ -985,7 +992,7 @@ namespace lib
} }
else else
{ {
log.debug( $"For {type.Name} use GetUninitializedObject" ); log.debug( $"For {type.FriendlyName()} use GetUninitializedObject" );
obj = System.Runtime.Serialization.FormatterServices.GetUninitializedObject( type ); obj = System.Runtime.Serialization.FormatterServices.GetUninitializedObject( type );
} }
@ -1007,7 +1014,7 @@ namespace lib
if( obj == null ) if( obj == null )
{ {
log.warn( $"Could not create object of type {type.Name}" ); log.warn( $"Could not create object of type {type.FriendlyName()}" );
return obj; return obj;
} }
@ -1061,7 +1068,7 @@ namespace lib
{ {
//Assembly ass = type.Assembly; //Assembly ass = type.Assembly;
//string assName = ass.GetName().Name; //string assName = ass.GetName().FriendlyName();
return type.FullName; // + ", " + assName; return type.FullName; // + ", " + assName;
} }
@ -1176,7 +1183,7 @@ namespace lib
if( mType != type ) if( mType != type )
{ {
log.info( $"Coll: {mType.Name} {mi?.Name} != {type.Name}" ); log.info( $"Coll: {mType.FriendlyName()} {mi?.Name} != {type.FriendlyName()}" );
writer.WriteAttributeString( "_.t", getTypeName( type ) ); writer.WriteAttributeString( "_.t", getTypeName( type ) );
} }
@ -1428,7 +1435,7 @@ namespace lib
if( mi is PropertyInfo pi ) typeOfMember = pi.PropertyType; if( mi is PropertyInfo pi ) typeOfMember = pi.PropertyType;
if( typeOfMember != type ) if( typeOfMember != type )
{ {
log.info( $"SerArr {typeOfMember.Name} {mi?.Name} != {type.Name}" ); log.info( $"SerArr {typeOfMember.FriendlyName()} {mi?.Name} != {type.FriendlyName()}" );
writer.WriteAttributeString( "_.t", getTypeName( type ) ); writer.WriteAttributeString( "_.t", getTypeName( type ) );
} }