From 1fd02d14605352b8b18c48cc245c87bb2346e2c9 Mon Sep 17 00:00:00 2001 From: Marc Hernandez Date: Sun, 2 Jun 2024 16:26:11 -0700 Subject: [PATCH] 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 --- Utilities.cs | 45 +++++++++++++++++++++++-- logging/GC.cs | 80 +++++++++++++++++++++++++++++++++++++++++--- logging/Log.cs | 6 ++-- ser/XmlFormatter2.cs | 29 ++++++++++------ 4 files changed, 140 insertions(+), 20 deletions(-) diff --git a/Utilities.cs b/Utilities.cs index 7f9cefd..3f3f10a 100644 --- a/Utilities.cs +++ b/Utilities.cs @@ -2,17 +2,17 @@ // Distributed under the MIT license. See the LICENSE.md file in the project root for more information. // // Copyright (c) 2010-2012 SharpDX - Alexandre Mutel -// +// // Permission is hereby granted, free of charge, to any person obtaining a copy // of this software and associated documentation files (the "Software"), to deal // in the Software without restriction, including without limitation the rights // to use, copy, modify, merge, publish, distribute, sublicense, and/or sell // copies of the Software, and to permit persons to whom the Software is // furnished to do so, subject to the following conditions: -// +// // The above copyright notice and this permission notice shall be included in // all copies or substantial portions of the Software. -// +// // THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR // IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, // FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE @@ -43,6 +43,45 @@ namespace lib public static class Util { + /* + public static string StringJoin( string separator, IEnumerable 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(this IEnumerable 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 public static unsafe void CopyMemory(IntPtr dest, IntPtr src, int sizeInBytesToCopy) diff --git a/logging/GC.cs b/logging/GC.cs index 30a40ca..e6cb153 100644 --- a/logging/GC.cs +++ b/logging/GC.cs @@ -29,7 +29,15 @@ public class RuntimeGCEventsPrinter "TypeLoad/Start", "Method/R2RGetEntryPointStart", "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}" ); @@ -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 LogCategoryFunc( string catIn ) { return ( TraceEvent te ) => @@ -64,11 +77,69 @@ public class RuntimeGCEventsPrinter 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 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 +// 0 ) @@ -145,7 +216,8 @@ public class RuntimeGCEventsPrinter source.Kernel.All += LogCategoryFunc( "kernel" ); - source.Dynamic.All += LogCategoryFunc( "dynamic" ); + // Doesnt seem to be too interesting. + //source.Dynamic.All += LogCategoryFunc( "dynamic" ); try diff --git a/logging/Log.cs b/logging/Log.cs index 433fba3..1f2566f 100644 --- a/logging/Log.cs +++ b/logging/Log.cs @@ -79,7 +79,7 @@ static public class log static log() { - /* + //* { 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 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 ); diff --git a/ser/XmlFormatter2.cs b/ser/XmlFormatter2.cs index 1805915..7f27587 100644 --- a/ser/XmlFormatter2.cs +++ b/ser/XmlFormatter2.cs @@ -147,6 +147,13 @@ namespace lib public class XmlFormatter2 : IFormatter { + + + + + + + public StreamingContext Context { get; set; } private XmlFormatter2Cfg _cfg = new(); @@ -302,7 +309,7 @@ namespace lib { 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 ) { @@ -337,7 +344,7 @@ namespace lib } 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; @@ -709,7 +716,7 @@ namespace lib 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 ); @@ -754,7 +761,7 @@ namespace lib 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" ); int refInt = refString.Length > 0 ? Convert.ToInt32( refString ) : -1; @@ -799,7 +806,7 @@ namespace lib 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 ) ) { @@ -975,7 +982,7 @@ namespace lib 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 ); if( cons != null) @@ -985,7 +992,7 @@ namespace lib } else { - log.debug( $"For {type.Name} use GetUninitializedObject" ); + log.debug( $"For {type.FriendlyName()} use GetUninitializedObject" ); obj = System.Runtime.Serialization.FormatterServices.GetUninitializedObject( type ); } @@ -1007,7 +1014,7 @@ namespace lib 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; } @@ -1061,7 +1068,7 @@ namespace lib { //Assembly ass = type.Assembly; - //string assName = ass.GetName().Name; + //string assName = ass.GetName().FriendlyName(); return type.FullName; // + ", " + assName; } @@ -1176,7 +1183,7 @@ namespace lib 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 ) ); } @@ -1428,7 +1435,7 @@ namespace lib if( mi is PropertyInfo pi ) typeOfMember = pi.PropertyType; 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 ) ); }