diff --git a/db/DB.cs b/db/DB.cs index 7f35440..632ced9 100644 --- a/db/DB.cs +++ b/db/DB.cs @@ -5,217 +5,221 @@ using static Optional.OptionExtensions; using static System.Collections.Immutable.ImmutableInterlocked; /* - ???? Should we have an explicit transaction class/ID? - ???? Should we split things into threaded vs action +???? Should we have an explicit transaction class/ID? +???? Should we split things into threaded vs action */ -namespace db +namespace db; + +public enum CommitResults { + Invalid, + Perfect, + Collisions, +} - public enum CommitResults +public interface IID +{ + TS id { get; } +} + +public class DB where T : IID +{ + object m_lock = new object(); + + //Current snapshot of the DB. + ImmutableDictionary m_objs = ImmutableDictionary.Empty; + + //List of committed Ids based on when they were committed. + ImmutableList m_committed = ImmutableList.Empty; + + ImmutableDictionary Objects => m_objs; + + public DB() { - Invalid, - Perfect, - Collisions, + LogGC.RegisterObjectId( m_lock ); } - public interface IID + // @@@@ TODO This returns an entity that can be changing. It should be a lazy instantiated copy + public Option lookup( TID id ) { - TS id { get; } + if( m_objs.TryGetValue( id, out T obj ) ) + { + return obj.Some(); + } + else + { + // LOG + } + + return obj.None(); } - public class DB where T : IID + public (Tx, Option) checkout( TID id ) { - //Current snapshot of the DB. - ImmutableDictionary m_objs = ImmutableDictionary.Empty; + var tx = new Tx( m_committed.Count, m_activeTransaction, this ); - //List of committed Ids based on when they were committed. - ImmutableList m_committed = ImmutableList.Empty; + var v = lookup( id ); - ImmutableDictionary Objects => m_objs; + v.Match( t => { + tx.checkout( id ); + }, () => { + } ); - // @@@@ TODO This returns an entity that can be changing. It should be a lazy instantiated copy - public Option lookup( TID id ) + return (tx, v); + } + + public Tx checkout( TID id, out Option tOut ) + { + var (tx, v) = checkout(id); + + tOut = v; + + return tx; + } + + public Tx checkout() + { + var tx = new Tx( m_committed.Count, m_activeTransaction, this ); + + return tx; + } + + public CommitResults commit( ref Tx co ) + { + co = null; + return commit_internal_single( co ); + } + + public ImmutableDictionary getSnapshot() + { + ImmutableDictionary res = m_objs; + return res; + } + + + internal CommitResults commit_internal_single( Tx tx ) + { + //var collision = false; + + //Check for previously committed things + var start = tx.Start; + + var curCommitted = m_committed; + + foreach( var t in tx.Checkouts ) { - if( m_objs.TryGetValue( id, out T obj ) ) + for( int i = start; i < curCommitted.Count; ++i ) { - return obj.Some(); - } - else - { - // LOG - } - - return obj.None(); - } - - public (Tx, Option) checkout( TID id ) - { - var tx = new Tx( m_committed.Count, m_activeTransaction, this ); - - var v = lookup( id ); - - v.Match( t => { - tx.checkout( id ); - }, () => { - } ); - - return (tx, v); - } - - public Tx checkout( TID id, out Option tOut ) - { - var (tx, v) = checkout(id); - - tOut = v; - - return tx; - } - - public Tx checkout() - { - var tx = new Tx( m_committed.Count, m_activeTransaction, this ); - - return tx; - } - - public CommitResults commit( ref Tx co ) - { - co = null; - return commit_internal_single( co ); - } - - public ImmutableDictionary getSnapshot() - { - ImmutableDictionary res = m_objs; - return res; - } - - - internal CommitResults commit_internal_single( Tx tx ) - { - //var collision = false; - - //Check for previously committed things - var start = tx.Start; - - var curCommitted = m_committed; - - foreach( var t in tx.Checkouts ) - { - for( int i = start; i < curCommitted.Count; ++i ) + if( !t.id.Equals( curCommitted[i] ) ) { } + else { - if( !t.id.Equals( curCommitted[i] ) ) { } - else - { - //collision = true; - return CommitResults.Collisions; - } + //collision = true; + return CommitResults.Collisions; } } + } - // @@@@ LOCK - lock( m_committed ) + // @@@@ LOCK + lock( m_committed ) + { + TID[] committed = new TID[tx.Checkouts.Count]; + + for( var i = 0; i < tx.Checkouts.Count; ++i ) { - TID[] committed = new TID[tx.Checkouts.Count]; - - for( var i = 0; i < tx.Checkouts.Count; ++i ) - { - committed[i] = tx.Checkouts[i].id; - m_objs = m_objs.Add( tx.Checkouts[i].id, tx.Checkouts[i] ); - } - - m_committed = m_committed.AddRange(committed); - - foreach( var v in tx.Adds ) - { - m_objs = m_objs.Add( v.id, v ); - } - - return CommitResults.Perfect; + committed[i] = tx.Checkouts[i].id; + m_objs = m_objs.Add( tx.Checkouts[i].id, tx.Checkouts[i] ); } - } + m_committed = m_committed.AddRange(committed); - - Option> m_activeTransaction = Option.None>(); - - } - - public enum TxStates - { - Invalid, - Running, - Committed, - } - - - //This only works for a single thread - public class Tx: IDisposable where T : IID - { - internal ImmutableList Checkouts => m_checkouts; - internal TxStates State => m_state; - internal int Start => m_start; - internal ImmutableList Adds => m_adds; - - internal Tx( int start, DB db ) - : - this(start, Option.None>(), db) - { - } - - internal Tx( int start, Option> parentTx, DB db ) - { - m_start = start; - m_parentTx = parentTx; - m_childTx = m_childTx.Add(this); - m_db = db; - m_state = TxStates.Running; - } - - public void Dispose() - { - // Dispose of unmanaged resources. - Dispose( true ); - // Suppress finalization. - GC.SuppressFinalize( this ); - } - - public void Dispose(bool isFromDispose ) - { - if( isFromDispose ) + foreach( var v in tx.Adds ) { - m_db.commit_internal_single( this ); + m_objs = m_objs.Add( v.id, v ); } + + return CommitResults.Perfect; } - - public Option checkout( TID id ) - { - var v = m_db.lookup( id ); - - v.MatchSome( t => { m_checkouts = m_checkouts.Add( t ); } ); - - return v; - } - - public void add( T obj ) - { - m_adds = m_adds.Add(obj); - } - - - int m_start = -1; - DB m_db; - - //Do we need these? Do we need both? - Option> m_parentTx; - ImmutableList> m_childTx = ImmutableList>.Empty; - - TxStates m_state = TxStates.Invalid; - ImmutableList m_checkouts = ImmutableList.Empty; - - // New objects created this pass - ImmutableList m_adds = ImmutableList.Empty; } + + + Option> m_activeTransaction = Option.None>(); + +} + +public enum TxStates +{ + Invalid, + Running, + Committed, +} + + +//This only works for a single thread +public class Tx: IDisposable where T : IID +{ + internal ImmutableList Checkouts => m_checkouts; + internal TxStates State => m_state; + internal int Start => m_start; + internal ImmutableList Adds => m_adds; + + internal Tx( int start, DB db ) + : + this(start, Option.None>(), db) + { + } + + internal Tx( int start, Option> parentTx, DB db ) + { + m_start = start; + m_parentTx = parentTx; + m_childTx = m_childTx.Add(this); + m_db = db; + m_state = TxStates.Running; + } + + public void Dispose() + { + // Dispose of unmanaged resources. + Dispose( true ); + // Suppress finalization. + GC.SuppressFinalize( this ); + } + + public void Dispose(bool isFromDispose ) + { + if( isFromDispose ) + { + m_db.commit_internal_single( this ); + } + } + + public Option checkout( TID id ) + { + var v = m_db.lookup( id ); + + v.MatchSome( t => { m_checkouts = m_checkouts.Add( t ); } ); + + return v; + } + + public void add( T obj ) + { + m_adds = m_adds.Add(obj); + } + + + int m_start = -1; + DB m_db; + + //Do we need these? Do we need both? + Option> m_parentTx; + ImmutableList> m_childTx = ImmutableList>.Empty; + + TxStates m_state = TxStates.Invalid; + ImmutableList m_checkouts = ImmutableList.Empty; + + // New objects created this pass + ImmutableList m_adds = ImmutableList.Empty; } diff --git a/logging/GC.cs b/logging/GC.cs index e6cb153..a8558a8 100644 --- a/logging/GC.cs +++ b/logging/GC.cs @@ -1,42 +1,109 @@ +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 class RuntimeGCEventsPrinter +public static class LogGCExt { - static ImmutableHashSet blacklist; - static ImmutableHashSet stacklist; + public static string MethodInfo( TraceEvent te, string prefix = "Method" ) + { + return $"{te.PayloadStringByName($"{prefix}Namespace")}.{te.PayloadStringByName($"{prefix}Name")}{te.PayloadStringByName($"{prefix}Signature")}"; + } - static RuntimeGCEventsPrinter() + 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( - "Method/ILToNativeMap", + "FAKE_TEST", "GC/BulkMovedObjectRanges", + + /* "GC/BulkSurvivingObjectRanges", - "GC/FinalizeObject", - "Type/BulkType", - "GC/SetGCHandle", - "GC/DestoryGCHandle", - "TypeLoad/Start", - "Method/R2RGetEntryPointStart", - "Method/MethodDetails", - "Method/MemoryAllocatedForJitCode", - "Method/JittingStarted", "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}" ); @@ -49,11 +116,28 @@ public class RuntimeGCEventsPrinter } - public static string MethodInfo( TraceEvent te, string prefix = "Method" ) + static public void RegisterObjectId( object obj ) { - return $"{te.PayloadStringByName($"{prefix}Namespace")}.{te.PayloadStringByName($"{prefix}Name")}{te.PayloadStringByName($"{prefix}Signature")}"; + /* + 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 ) => @@ -63,7 +147,7 @@ public class RuntimeGCEventsPrinter if( blacklist.Contains( te.EventName )) return; { - var methodBeingCompiledNamespace = te.PayloadStringByName("MethodBeingCompiledNamespace") ?? ""; + var methodBeingCompiledNamespace = te.Get("MethodBeingCompiledNamespace"); if( ( methodBeingCompiledNamespace.StartsWith( "Microsoft" ) || methodBeingCompiledNamespace.StartsWith( "System" ) ) ) return; } @@ -78,6 +162,7 @@ public class RuntimeGCEventsPrinter } + { var ns = te.PayloadStringByName("TypeLoad/Stop") ?? ""; if( ns.StartsWith( "Godot" ) ) return; @@ -104,40 +189,185 @@ public class RuntimeGCEventsPrinter // Custom event displays if( te.EventName == "Method/LoadVerbose" ) { - log.info( $"{te.PayloadStringByName("OptimizationTier")} {MethodInfo(te)}", cat: te.EventName ); + 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" ) ) { - log.info( $"Inlining {te.PayloadStringByName("FailReason")} {te.PayloadStringByName("OptimizationTier")} {MethodInfo(te, "MethodBeingCompiled")}", cat: te.EventName ); + 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; + /* + var typeName = te.PayloadStringByName( "TypeName" ); + if( typeName.StartsWith( "Godot." ) ) + return; + + log.info( $"{typeName} Level: {te.PayloadStringByName( "LoadLevel" )}", cat: te.EventName ); + //*/ - 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 ); + 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( -//76 CHARACTERS -//( "LockID" ); + var objId = te.Get( "AssociatedObjectID" ); - var teStr = te.ToString().Replace("ClrInstanceID=\"0\"", "" ); + var testObj = Marshal.GetIUnknownForObject(objId); - var teStrSlice = teStr.AsSpan( 74, teStr.Length - (74 + 1 + 1) ); + var intPtrStr = te.PayloadStringByName( "AssociatedObjectID" ).Substring( 2 ); - log.debug( $"{logDetails}{teStrSlice}", cat: te.EventName ); + 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 + //> 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 ) { @@ -211,10 +477,11 @@ public class RuntimeGCEventsPrinter var source = new EventPipeEventSource( session.EventStream ); + source.Clr.GCAllocationTick += OnAllocTick; - source.Clr.All += LogCategoryFunc( "clr" ); + //source.Clr.All += LogCategoryFunc( "clr" ); - source.Kernel.All += LogCategoryFunc( "kernel" ); + //source.Kernel.All += LogCategoryFunc( "kernel" ); // Doesnt seem to be too interesting. //source.Dynamic.All += LogCategoryFunc( "dynamic" ); @@ -231,4 +498,9 @@ public class RuntimeGCEventsPrinter } } } + + private static void OnAllocTick( GCAllocationTickTraceData data ) + { + } } + diff --git a/logging/Log.cs b/logging/Log.cs index 1f2566f..f915062 100644 --- a/logging/Log.cs +++ b/logging/Log.cs @@ -77,9 +77,13 @@ public struct SourceLoc static public class log { + //static + static log() { - //* + log.high( $"Starting tracers" ); + + /* { var start = new ThreadStart( StartGCWatcher ); @@ -90,6 +94,17 @@ static public class log } // */ + //log.info( $"Tracing.Program.CreateTracingSession" ); + //var task = log.call( Tracing.Program.CreateTracingSession( false, true, 64 ) ); + + //* + log.info( $"Tracing.MemoryPipe" ); + + var memoryPipe = log.call( () => new Tracing.MemoryPipe() ); + + //var pipeTask = log.call( () => memoryPipe.StartAsync( true ) ); + //*/ + /* { var start = new ThreadStart( StartTracing ); @@ -112,7 +127,7 @@ static public class log } var processId = Process.GetCurrentProcess().Id; - RuntimeGCEventsPrinter.PrintRuntimeGCEvents( processId ); + LogGC.PrintRuntimeGCEvents( processId ); } static void StartTracing() @@ -327,6 +342,27 @@ static public class log #endregion // Util #region Forwards + static public T call( Func func, [CallerMemberName] string dbgName = "", [CallerFilePath] string dbgPath = "", [CallerLineNumber] int dbgLine = -1, [CallerArgumentExpression("func")] string dbgExp = "" ) + { + log.info( $"Calling {dbgExp}" ); + var val = func(); + log.info( $"| Got {val}" ); + return val; + } + + static public T call( T val, [CallerMemberName] string dbgName = "", [CallerFilePath] string dbgPath = "", [CallerLineNumber] int dbgLine = -1, [CallerArgumentExpression("val")] string dbgExp = "" ) + { + log.info( $"Called {dbgExp} Got: {val}" ); + return val; + } + + static public void call( Action func, [CallerMemberName] string dbgName = "", [CallerFilePath] string dbgPath = "", [CallerLineNumber] int dbgLine = -1, [CallerArgumentExpression("func")] string dbgExp = "" ) + { + log.info( $"Calling {dbgExp}" ); + func(); + log.info( $"| Done" ); + } + static public void fatal( string msg, string cat = "", object? obj = null, [CallerFilePath] string path = "", [CallerLineNumber] int line = -1, [CallerMemberName] string member = "", [CallerArgumentExpression("msg")] string dbgExp = "" ) { logBase( msg, LogType.Fatal, path, line, member, cat, dbgExp, obj ); @@ -461,13 +497,6 @@ static public class log s_endpoints = endpoints; - var start = new ThreadStart( run ); - - s_thread = new Thread( start ); - s_thread.Priority = ThreadPriority.BelowNormal; - s_thread.Name = $"Logging"; - s_thread.Start(); - var dir = Path.GetDirectoryName( filename ); if( dir?.Length > 0 ) @@ -482,8 +511,43 @@ static public class log s_errorStream = new FileStream( filename + ".error", FileMode.Append, FileAccess.Write ); s_errorWriter = new StreamWriter( s_errorStream ); + { + var time = DateTime.Now; + // Header for this run + var blankLine = new LogEvent( LogType.Raw, $"", "", 0, "", "lib.time", "", null ); + var beginLine = new LogEvent( LogType.Raw, $"Begin B E G I N ******************************************************************************************************************", "", 0, "", "lib.time", "", null ); + var timeLine = new LogEvent( LogType.Raw, $"D A T E {time.Year}/{time.Month.ToString("00")}/{time.Day.ToString("00")} T I M E {time.Hour.ToString("00")}:{time.Minute.ToString("00")}:{time.Second.ToString("00")}.{time.Millisecond.ToString("000")}{time.Microsecond.ToString("000")}", "", 0, "", "lib.time", "", null ); - info( $"Logging in {filename}" ); + + //writeToAll( endLine ); + writeToAll( blankLine ); + writeToAll( blankLine ); + writeToAll( beginLine ); + writeToAll( blankLine ); + writeToAll( timeLine ); + writeToAll( blankLine ); + + } + + LogEvent msgStartupBegin = new LogEvent( LogType.Info, $"startup BEGIN", "", 0, "", "log.startup", "", null ); + writeToAll( msgStartupBegin ); + + LogEvent msgFilename = new LogEvent( LogType.Info, $"Logging in {filename}", "", 0, "", "log.startup", "", null ); + writeToAll( msgFilename ); + + var start = new ThreadStart( run ); + + s_thread = new Thread( start ); + s_thread.Priority = ThreadPriority.BelowNormal; + s_thread.Name = $"Logging"; + s_thread.Start(); + + + + //info( $"Logging in {filename}" ); + + + LogGC.RegisterObjectId( s_lock ); //Debug.Listeners.Add( this ); @@ -499,8 +563,10 @@ static public class log */ + //LogEvent msgStartupBegin = new LogEvent( LogType.Info, $"startup END", "", 0, "", "lib.time", "", null ); + //writeToAll( msgStartupBegin ); - info( $"startup" ); + info( $"startup END", cat: "log.startup" ); } @@ -508,22 +574,6 @@ static public class log static void run() { - var time = DateTime.Now; - // Header for this run - var blankLine = new LogEvent( LogType.Raw, $"", "", 0, "", "lib.time", "", null ); - var beginLine = new LogEvent( LogType.Raw, $"Begin B E G I N ******************************************************************************************************************", "", 0, "", "lib.time", "", null ); - var endLine = new LogEvent( LogType.Raw, $"End E N D ******************************************************************************************************************", "", 0, "", "lib.time", "", null ); - var timeLine = new LogEvent( LogType.Raw, $"D A T E {time.Year}/{time.Month.ToString("00")}/{time.Day.ToString("00")} T I M E {time.Hour.ToString("00")}:{time.Minute.ToString("00")}:{time.Second.ToString("00")}.{time.Millisecond.ToString("000")}{time.Microsecond.ToString("000")}", "", 0, "", "lib.time", "", null ); - - - //writeToAll( endLine ); - writeToAll( blankLine ); - writeToAll( blankLine ); - writeToAll( beginLine ); - writeToAll( blankLine ); - writeToAll( timeLine ); - writeToAll( blankLine ); - while( s_running ) { @@ -536,6 +586,7 @@ static public class log Thread.Sleep( 0 ); } + var endLine = new LogEvent( LogType.Raw, $"End E N D ******************************************************************************************************************", "", 0, "", "lib.time", "", null ); writeToAll( endLine ); } diff --git a/prof/AddressStack.cs b/prof/AddressStack.cs new file mode 100644 index 0000000..c766c9f --- /dev/null +++ b/prof/AddressStack.cs @@ -0,0 +1,41 @@ +using System.Collections.Generic; + +namespace Tracing +{ + public class AddressStack + { + // the first frame is the address of the last called method + private readonly List _stack; + + public AddressStack(int capacity) + { + _stack = new List(capacity); + } + + // No need to override GetHashCode because we don't want to use it as a key in a dictionary + public override bool Equals(object obj) + { + if (obj == null) return false; + + var stack = obj as AddressStack; + if (stack == null) return false; + + var frameCount = _stack.Count; + if (frameCount != stack._stack.Count) return false; + + for (int i = 0; i < frameCount; i++) + { + if (_stack[i] != stack._stack[i]) return false; + } + + return true; + } + + public IReadOnlyList Stack => _stack; + + public void AddFrame(ulong address) + { + _stack.Add(address); + } + } +} diff --git a/prof/Memory.cs b/prof/Memory.cs new file mode 100644 index 0000000..3d7913e --- /dev/null +++ b/prof/Memory.cs @@ -0,0 +1,314 @@ +using Microsoft.Diagnostics.Tracing; +using Microsoft.Diagnostics.Tracing.Parsers; +using Microsoft.Diagnostics.Tracing.Parsers.Clr; +using Microsoft.Diagnostics.Tracing.Parsers.Kernel; +using Microsoft.Diagnostics.Tracing.Session; +using ProfilerHelpers; +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Threading; +using System.Threading.Tasks; + +namespace Tracing +{ + public class Memory + { + private readonly TraceEventSession _session; + private readonly PerProcessProfilingState _processes; + + // because we are not interested in self monitoring + private readonly int _currentPid; + + private int _started = 0; + + public Memory( TraceEventSession session, PerProcessProfilingState processes ) + { + _session = session; + _processes = processes; + _currentPid = Process.GetCurrentProcess().Id; + } + + public async Task StartAsync( bool allAllocations ) + { + if( Interlocked.CompareExchange( ref _started, 1, 0 ) == 1 ) + { + throw new InvalidOperationException( "Impossible to start profiling more than once." ); + } + + await Task.Factory.StartNew( () => + { + using( _session ) + { + log.info( $"SetupProviders" ); + SetupProviders( _session, allAllocations ); + + log.info( $"SetupListeners" ); + SetupListeners( _session.Source ); + + log.info( $"Source.Process()" ); + while( _session.Source.Process() ) + { + Task.Delay( 1 ); + } + + log.info( $"Done" ); + } + } ); + } + + private void SetupProviders( TraceEventSession session, bool noSampling ) + { + // Note: the kernel provider MUST be the first provider to be enabled + // If the kernel provider is not enabled, the callstacks for CLR events are still received + // but the symbols are not found (except for the application itself) + // Maybe a TraceEvent implementation details triggered when a module (image) is loaded + var success = true; + + //* + log.info( $"EnableKernelProvider" ); + success = log.call( session.EnableKernelProvider( KernelTraceEventParser.Keywords.None | +// KernelTraceEventParser.Keywords.ImageLoad | +// KernelTraceEventParser.Keywords.Process + 0 , + KernelTraceEventParser.Keywords.None + ) ); + log.info( $"EnableKernelProvider {success}" ); + //*/ + + // The CLR source code indicates that the provider must be set before the monitored application starts + // Note: no real difference between High and Low + ClrTraceEventParser.Keywords eventsKeyword = noSampling + ? ClrTraceEventParser.Keywords.GCSampledObjectAllocationLow | ClrTraceEventParser.Keywords.GCSampledObjectAllocationHigh + : ClrTraceEventParser.Keywords.GCSampledObjectAllocationLow + ; + + log.info( $"EnableProvider" ); + success = log.call( session.EnableProvider( + ClrTraceEventParser.ProviderGuid, + TraceEventLevel.Verbose, // this is needed in order to receive GCSampledObjectAllocation event + (ulong)( + + eventsKeyword | + + // required to receive the BulkType events that allows + // mapping between the type ID received in the allocation events + ClrTraceEventParser.Keywords.GCHeapAndTypeNames | + ClrTraceEventParser.Keywords.Type | + + // events related to JITed methods + ClrTraceEventParser.Keywords.Jit | // Turning on JIT events is necessary to resolve JIT compiled code + ClrTraceEventParser.Keywords.JittedMethodILToNativeMap | // This is needed if you want line number information in the stacks + ClrTraceEventParser.Keywords.Loader | // You must include loader events as well to resolve JIT compiled code. + + // this is mandatory to get the callstacks in each CLR event payload. + //ClrTraceEventParser.Keywords.Stack | + + 0 + ) + ) ); + log.info( $"EnableProvider {success}" ); + + + // Note: ClrRundown is not needed because only new processes will be monitored + } + + private void SetupListeners( ETWTraceEventSource source ) + { + // register for high and low keyword + // if both are set, each allocation will trigger an event (beware performance issues...) + source.Clr.GCSampledObjectAllocation += OnSampleObjectAllocation; + + // required to receive the mapping between type ID (received in GCSampledObjectAllocation) + // and their name (received in TypeBulkType) + source.Clr.TypeBulkType += OnTypeBulkType; + + // messages to get callstacks + // the correlation seems to be as "simple" as taking the last event on the same thread + source.Clr.ClrStackWalk += OnClrStackWalk; + + // needed to get JITed method details + source.Clr.MethodLoadVerbose += OnMethodDetails; + source.Clr.MethodDCStartVerboseV2 += OnMethodDetails; + + source.Clr.ContentionLockCreated += OnLockCreated; + source.Clr.ContentionStart += OnLockStart; + source.Clr.ContentionStop += OnLockStop; + + // get notified when a module is load to map the corresponding symbols + source.Kernel.ImageLoad += OnImageLoad; + } + + private void OnLockCreated( ContentionLockCreatedTraceData data ) + { + } + + private void OnLockStart( ContentionStartTraceData data ) + { + + } + + private void OnLockStop( ContentionStopTraceData data ) + { + } + + private void OnImageLoad( ImageLoadTraceData data ) + { + if( FilterOutEvent( data ) ) + return; + + GetProcessMethods( data.ProcessID ).AddModule( data.FileName, data.ImageBase, data.ImageSize ); + + log.info($"{data.ProcessID}.{data.ThreadID} --> {data.FileName}"); + } + + private void OnMethodDetails( MethodLoadUnloadVerboseTraceData data ) + { + if( FilterOutEvent( data ) ) + return; + + // care only about jitted methods + if( !data.IsJitted ) + return; + + var method = GetProcessMethods( data.ProcessID ) + .Add( data.MethodStartAddress, data.MethodSize, data.MethodNamespace, data.MethodName, data.MethodSignature ); + + log.info( $"0x{data.MethodStartAddress.ToString( "x12" )} - {data.MethodSize,6} | {data.MethodName}" ); + } + + private MethodStore GetProcessMethods( int pid ) + { + if( !_processes.Methods.TryGetValue( pid, out var methods ) ) + { + methods = new MethodStore( pid ); + _processes.Methods[pid] = methods; + } + return methods; + } + + + private void OnSampleObjectAllocation( GCSampledObjectAllocationTraceData data ) + { + if( FilterOutEvent( data ) ) + return; + + var typeName = GetProcessTypeName( data.ProcessID, data.TypeID ); + if( data.TotalSizeForTypeSample >= 85000 ) + { + var message = $"{data.ProcessID}.{data.ThreadID} - {data.TimeStampRelativeMSec,12} | Alloc {GetProcessTypeName( data.ProcessID, data.TypeID )} ({data.TotalSizeForTypeSample})"; + log.info( message ); + } + GetProcessAllocations( data.ProcessID ) + .AddAllocation( + data.ThreadID, + (ulong)data.TotalSizeForTypeSample, + (ulong)data.ObjectCountForTypeSample, + typeName + ); + } + + private ProcessAllocations GetProcessAllocations( int pid ) + { + if( !_processes.Allocations.TryGetValue( pid, out var allocations ) ) + { + allocations = new ProcessAllocations( pid ); + _processes.Allocations[pid] = allocations; + } + return allocations; + } + + private void OnClrStackWalk( ClrStackWalkTraceData data ) + { + if( FilterOutEvent( data ) ) + return; + + //var message = $"{data.ProcessID}.{data.ThreadID} - {data.TimeStampRelativeMSec,12} | {data.FrameCount} frames"; + //log.info(message); + + var callstack = BuildCallStack( data ); + GetProcessAllocations( data.ProcessID ).AddStack( data.ThreadID, callstack ); + //DumpStack(data); + } + + private AddressStack BuildCallStack( ClrStackWalkTraceData data ) + { + var length = data.FrameCount; + AddressStack stack = new AddressStack( length ); + + // frame 0 is the last frame of the stack (i.e. last called method) + for( int i = 0; i < length; i++ ) + { + stack.AddFrame( data.InstructionPointer( i ) ); + } + + return stack; + } + + private void DumpStack( ClrStackWalkTraceData data ) + { + var methods = GetProcessMethods( data.ProcessID ); + for( int i = 0; i < data.FrameCount; i++ ) + { + var address = data.InstructionPointer( i ); + log.info( methods.GetFullName( address ) ); + } + log.info( $"" ); + } + + private void OnTypeBulkType( GCBulkTypeTraceData data ) + { + if( FilterOutEvent( data ) ) + return; + + ProcessTypeMapping mapping = GetProcessTypesMapping( data.ProcessID ); + for( int currentType = 0; currentType < data.Count; currentType++ ) + { + GCBulkTypeValues value = data.Values( currentType ); + mapping[value.TypeID] = value.TypeName; + } + } + + private ProcessTypeMapping GetProcessTypesMapping( int pid ) + { + ProcessTypeMapping mapping; + if( !_processes.Types.TryGetValue( pid, out mapping ) ) + { + AssociateProcess( pid ); + + mapping = new ProcessTypeMapping( pid ); + _processes.Types[pid] = mapping; + } + return mapping; + } + + private void AssociateProcess( int pid ) + { + try + { + _processes.Names[pid] = Process.GetProcessById( pid ).ProcessName; + } + catch( Exception ) + { + log.info( $"? {pid}" ); + // we might not have access to the process + } + } + + private string GetProcessTypeName( int pid, ulong typeID ) + { + if( !_processes.Types.TryGetValue( pid, out var mapping ) ) + { + return typeID.ToString(); + } + + var name = mapping[typeID]; + return string.IsNullOrEmpty( name ) ? typeID.ToString() : name; + } + + private bool FilterOutEvent( TraceEvent data ) + { + return ( data.ProcessID == _currentPid ); + } + } +} diff --git a/prof/MemoryPipe.cs b/prof/MemoryPipe.cs new file mode 100644 index 0000000..1ec0b54 --- /dev/null +++ b/prof/MemoryPipe.cs @@ -0,0 +1,393 @@ +using Microsoft.Diagnostics.NETCore.Client; +using Microsoft.Diagnostics.Tracing; +using Microsoft.Diagnostics.Tracing.Etlx; +using Microsoft.Diagnostics.Tracing.Parsers; +using Microsoft.Diagnostics.Tracing.Parsers.Clr; +using Microsoft.Diagnostics.Tracing.Parsers.Kernel; +using Microsoft.Diagnostics.Tracing.Session; +using ProfilerHelpers; +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Diagnostics.Tracing; +using System.Threading; +using System.Threading.Tasks; +using TraceKeywords = Microsoft.Diagnostics.Tracing.Parsers.ClrTraceEventParser.Keywords; + +namespace Tracing +{ + public class MemoryPipe + { + private readonly DiagnosticsClient _client; + private readonly PerProcessProfilingState _processes; + + // because we are not interested in self monitoring + private readonly int _currentPid; + + private int _started = 0; + + Thread _thread; + + public MemoryPipe() + { + + _currentPid = Process.GetCurrentProcess().Id; + + _client = new DiagnosticsClient( _currentPid ); + + _processes = new(); + + + var threadStart = new ThreadStart( () => Start( true ) ); + _thread = new Thread( threadStart ); + _thread.Start(); + + + } + + //public async Task StartAsync( bool allAllocations ) + public void Start( bool allAllocations ) + { + if( Interlocked.CompareExchange( ref _started, 1, 0 ) == 1 ) + { + throw new InvalidOperationException( "Impossible to start profiling more than once." ); + } + + log.info( $"Starting MemoryPipe on thread {Thread.CurrentThread.ManagedThreadId}" ); + + 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 + ) ) + }; + + + //await Task.Factory.StartNew( () => { + using EventPipeSession session = _client.StartEventPipeSession( providers, false ); + + //log.info( $"SetupProviders" ); + //SetupProviders( session, allAllocations ); + var source = new EventPipeEventSource( session.EventStream ); + + + log.info( $"SetupListeners" ); + SetupListeners( source ); + + log.info( $"Run Process" ); + source.Process(); + + log.info( $"Done" ); + //} ); + } + + private void SetupProviders( TraceEventSession session, bool noSampling ) + { + // Note: the kernel provider MUST be the first provider to be enabled + // If the kernel provider is not enabled, the callstacks for CLR events are still received + // but the symbols are not found (except for the application itself) + // Maybe a TraceEvent implementation details triggered when a module (image) is loaded + var success = true; + + //* + log.info( $"EnableKernelProvider" ); + success = log.call( session.EnableKernelProvider( KernelTraceEventParser.Keywords.None | +// KernelTraceEventParser.Keywords.ImageLoad | +// KernelTraceEventParser.Keywords.Process + 0 , + KernelTraceEventParser.Keywords.None + ) ); + log.info( $"EnableKernelProvider {success}" ); + //*/ + + // The CLR source code indicates that the provider must be set before the monitored application starts + // Note: no real difference between High and Low + ClrTraceEventParser.Keywords eventsKeyword = noSampling + ? ClrTraceEventParser.Keywords.GCSampledObjectAllocationLow | ClrTraceEventParser.Keywords.GCSampledObjectAllocationHigh + : ClrTraceEventParser.Keywords.GCSampledObjectAllocationLow + ; + + log.info( $"EnableProvider" ); + success = log.call( session.EnableProvider( + ClrTraceEventParser.ProviderGuid, + TraceEventLevel.Verbose, // this is needed in order to receive GCSampledObjectAllocation event + (ulong)( + + eventsKeyword | + + // required to receive the BulkType events that allows + // mapping between the type ID received in the allocation events + ClrTraceEventParser.Keywords.GCHeapAndTypeNames | + ClrTraceEventParser.Keywords.Type | + + // events related to JITed methods + ClrTraceEventParser.Keywords.Jit | // Turning on JIT events is necessary to resolve JIT compiled code + ClrTraceEventParser.Keywords.JittedMethodILToNativeMap | // This is needed if you want line number information in the stacks + ClrTraceEventParser.Keywords.Loader | // You must include loader events as well to resolve JIT compiled code. + + // this is mandatory to get the callstacks in each CLR event payload. + //ClrTraceEventParser.Keywords.Stack | + + 0 + ) + ) ); + log.info( $"EnableProvider {success}" ); + + + // Note: ClrRundown is not needed because only new processes will be monitored + } + + private void SetupListeners( EventPipeEventSource source ) + { + // register for high and low keyword + // if both are set, each allocation will trigger an event (beware performance issues...) + //source.Clr.GCSampledObjectAllocation += OnSampleObjectAllocation; + source.Clr.GCAllocationTick += OnAllocTick; + + // required to receive the mapping between type ID (received in GCSampledObjectAllocation) + // and their name (received in TypeBulkType) + source.Clr.TypeBulkType += OnTypeBulkType; + + // messages to get callstacks + // the correlation seems to be as "simple" as taking the last event on the same thread + source.Clr.ClrStackWalk += OnClrStackWalk; + + // needed to get JITed method details + source.Clr.MethodLoadVerbose += OnMethodDetails; + source.Clr.MethodDCStartVerboseV2 += OnMethodDetails; + + source.Clr.ContentionLockCreated += OnLockCreated; + source.Clr.ContentionStart += OnLockStart; + source.Clr.ContentionStop += OnLockStop; + + // get notified when a module is load to map the corresponding symbols + source.Kernel.ImageLoad += OnImageLoad; + } + + private void OnAllocTick( GCAllocationTickTraceData data ) + { + if( FilterOutEvent( data ) ) + return; + + //log.info( $"*** RAW: {data}" ); + + //var callStack = data.CallStack(); + //var caller = callStack.Caller; + + //log.info( $"Call stack {callStack}" ); + + var thisThreadId = Thread.CurrentThread.ManagedThreadId; + + var typeName = GetProcessTypeName( data.ProcessID, data.TypeID ); + //if( data.TotalSizeForTypeSample >= 85000 ) + { + var message = $"{data.ThreadID}/{thisThreadId} Alloc {data.ObjectSize, 8} at 0x{data.Address:0000000000000000} in {data.TypeName} (or {GetProcessTypeName( data.ProcessID, data.TypeID )}) "; + log.info( message ); + } + GetProcessAllocations( data.ProcessID ) + .AddAllocation( + data.ThreadID, + (ulong)data.ObjectSize, + (ulong)1, + typeName + ); + } + + private void OnLockCreated( ContentionLockCreatedTraceData data ) + { + log.info( $"{data}" ); + } + + private void OnLockStart( ContentionStartTraceData data ) + { + log.info( $"{data}" ); + } + + private void OnLockStop( ContentionStopTraceData data ) + { + log.info( $"{data}" ); + } + + private void OnImageLoad( ImageLoadTraceData data ) + { + //if( FilterOutEvent( data ) ) + // return; + + log.info( $"{data}" ); + + //GetProcessMethods( data.ProcessID ).AddModule( data.FileName, data.ImageBase, data.ImageSize ); + + log.info($"{data.ProcessID}.{data.ThreadID} --> {data.FileName}"); + } + + private void OnMethodDetails( MethodLoadUnloadVerboseTraceData data ) + { + //if( FilterOutEvent( data ) ) + // return; + + //log.info( $"{data}" ); + + // care only about jitted methods + if( !data.IsJitted ) + return; + + var method = GetProcessMethods( data.ProcessID ) + .Add( data.MethodStartAddress, data.MethodSize, data.MethodNamespace, data.MethodName, data.MethodSignature ); + + //log.info( $"0x{data.MethodStartAddress.ToString( "x12" )} - {data.MethodSize,6} | {data.MethodName}" ); + } + + private MethodStore GetProcessMethods( int pid ) + { + if( !_processes.Methods.TryGetValue( pid, out var methods ) ) + { + methods = new MethodStore( pid ); + _processes.Methods[pid] = methods; + } + return methods; + } + + + private void OnSampleObjectAllocation( GCSampledObjectAllocationTraceData data ) + { + if( FilterOutEvent( data ) ) + return; + + //log.info( $"{data}" ); + + var typeName = GetProcessTypeName( data.ProcessID, data.TypeID ); + //if( data.TotalSizeForTypeSample >= 85000 ) + { + var message = $"{data.ProcessID}.{data.ThreadID} - {data.TimeStampRelativeMSec,12} | Alloc {GetProcessTypeName( data.ProcessID, data.TypeID )} ({data.TotalSizeForTypeSample})"; + log.info( message ); + } + GetProcessAllocations( data.ProcessID ) + .AddAllocation( + data.ThreadID, + (ulong)data.TotalSizeForTypeSample, + (ulong)data.ObjectCountForTypeSample, + typeName + ); + } + + private ProcessAllocations GetProcessAllocations( int pid ) + { + if( !_processes.Allocations.TryGetValue( pid, out var allocations ) ) + { + allocations = new ProcessAllocations( pid ); + _processes.Allocations[pid] = allocations; + } + return allocations; + } + + private void OnClrStackWalk( ClrStackWalkTraceData data ) + { + var message = $"{data.ProcessID}.{data.ThreadID} - {data.TimeStampRelativeMSec,12} | {data.FrameCount} frames"; + log.info(message); + + var callstack = BuildCallStack( data ); + GetProcessAllocations( data.ProcessID ).AddStack( data.ThreadID, callstack ); + //DumpStack(data); + } + + private AddressStack BuildCallStack( ClrStackWalkTraceData data ) + { + //log.info( $"{data}" ); + + var length = data.FrameCount; + AddressStack stack = new AddressStack( length ); + + // frame 0 is the last frame of the stack (i.e. last called method) + for( int i = 0; i < length; i++ ) + { + stack.AddFrame( data.InstructionPointer( i ) ); + } + + return stack; + } + + private void DumpStack( ClrStackWalkTraceData data ) + { + if( FilterOutEvent( data ) ) + return; + + log.info( $"{data}" ); + + var methods = GetProcessMethods( data.ProcessID ); + for( int i = 0; i < data.FrameCount; i++ ) + { + var address = data.InstructionPointer( i ); + log.info( methods.GetFullName( address ) ); + } + log.info( $"" ); + } + + private void OnTypeBulkType( GCBulkTypeTraceData data ) + { + + ProcessTypeMapping mapping = GetProcessTypesMapping( data.ProcessID ); + for( int currentType = 0; currentType < data.Count; currentType++ ) + { + GCBulkTypeValues value = data.Values( currentType ); + mapping[value.TypeID] = value.TypeName; + //log.info( $"{value}" ); + } + } + + private ProcessTypeMapping GetProcessTypesMapping( int pid ) + { + ProcessTypeMapping mapping; + if( !_processes.Types.TryGetValue( pid, out mapping ) ) + { + AssociateProcess( pid ); + + mapping = new ProcessTypeMapping( pid ); + _processes.Types[pid] = mapping; + } + return mapping; + } + + private void AssociateProcess( int pid ) + { + try + { + _processes.Names[pid] = Process.GetProcessById( pid ).ProcessName; + } + catch( Exception ) + { + log.info( $"? {pid}" ); + // we might not have access to the process + } + } + + private string GetProcessTypeName( int pid, ulong typeID ) + { + if( !_processes.Types.TryGetValue( pid, out var mapping ) ) + { + return typeID.ToString(); + } + + var name = mapping[typeID]; + return string.IsNullOrEmpty( name ) ? typeID.ToString() : name; + } + + private bool FilterOutEvent( TraceEvent data ) + { + return data.ThreadID == Thread.CurrentThread.ManagedThreadId; + //return false; // ( data.ProcessID == _currentPid ); + } + } +} diff --git a/prof/MethodInfo.cs b/prof/MethodInfo.cs new file mode 100644 index 0000000..248f5c6 --- /dev/null +++ b/prof/MethodInfo.cs @@ -0,0 +1,68 @@ +using System; + +namespace ProfilerHelpers +{ + public class MethodInfo + { + private readonly ulong _startAddress; + private readonly int _size; + private readonly string _fullName; + + internal MethodInfo(ulong startAddress, int size, string namespaceAndTypeName, string name, string signature) + { + _startAddress = startAddress; + _size = size; + _fullName = ComputeFullName(startAddress, namespaceAndTypeName, name, signature); + } + + private string ComputeFullName(ulong startAddress, string namespaceAndTypeName, string name, string signature) + { + var fullName = signature; + + // constructor case: name = .ctor | namespaceAndTypeName = A.B.typeName | signature = ... (parameters) + // --> A.B.typeName(parameters) + if (name == ".ctor") + { + return $"{namespaceAndTypeName}{ExtractParameters(signature)}"; + } + + // general case: name = Foo | namespaceAndTypeName = A.B.typeName | signature = ... (parameters) + // --> A.B.Foo(parameters) + fullName = $"{namespaceAndTypeName}.{name}{ExtractParameters(signature)}"; + return fullName; + } + + private string ExtractTypeName(string namespaceAndTypeName) + { + var pos = namespaceAndTypeName.LastIndexOf(".", StringComparison.Ordinal); + if (pos == -1) + { + return namespaceAndTypeName; + } + + // skip the . + pos++; + + return namespaceAndTypeName.Substring(pos); + } + + private string ExtractParameters(string signature) + { + var pos = signature.IndexOf(" ("); + if (pos == -1) + { + return "(???)"; + } + + // skip double space + pos += 2; + + var parameters = signature.Substring(pos); + return parameters; + } + + public ulong StartAddress => _startAddress; + public int Size => _size; + public string FullName => _fullName; + } +} diff --git a/prof/MethodStore.cs b/prof/MethodStore.cs new file mode 100644 index 0000000..39e0dd8 --- /dev/null +++ b/prof/MethodStore.cs @@ -0,0 +1,208 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Runtime.InteropServices; +using System.Text; + +namespace ProfilerHelpers +{ + public class MethodStore : IDisposable + { + // JITed methods information (start address + size + signature) + private readonly List _methods; + + // addresses from callstacks already matching (address -> full name) + private readonly Dictionary _cache; + + // for native methods, rely on dbghelp API + // so the process handle is required + private IntPtr _hProcess; + private Process _process; + private readonly int _pid; + + public MethodStore(int pid, bool loadModules = false) + { + // it may be possible to open the process + // in that case, _hProcess = IntPtr.Zero + _pid = pid; + + _methods = new List(1024); + _cache = new Dictionary(); + + _hProcess = BindToProcess(pid, loadModules); + } + + private IntPtr BindToProcess(int pid, bool loadModules) + { + try + { + _process = Process.GetProcessById(pid); + + if (!SymInitialize(_process.Handle, loadModules)) + return IntPtr.Zero; + + return _process.Handle; + } + catch (Exception x) + { + Console.WriteLine($"Error while binding pid #{pid} to DbgHelp:"); + Console.WriteLine(x.Message); + return IntPtr.Zero; + } + } + + private bool SymInitialize(IntPtr hProcess, bool loadModules = false) + { + // read https://docs.microsoft.com/en-us/windows/win32/api/dbghelp/nf-dbghelp-symsetoptions for more details + // maybe SYMOPT_NO_PROMPTS and SYMOPT_FAIL_CRITICAL_ERRORS could be used + NativeDbgHelp.SymSetOptions( + NativeDbgHelp.SYMOPT_DEFERRED_LOADS | // performance optimization + NativeDbgHelp.SYMOPT_UNDNAME // C++ names are not mangled + ); + + // https://docs.microsoft.com/en-us/windows/win32/api/dbghelp/nf-dbghelp-syminitialize + // search path for symbols: + // - The current working directory of the application + // - The _NT_SYMBOL_PATH environment variable + // - The _NT_ALTERNATE_SYMBOL_PATH environment variable + // + // passing false as last parameter means that we will need to call SymLoadModule64 + // each time a module is loaded in the process + return NativeDbgHelp.SymInitialize(hProcess, null, loadModules); + } + + public MethodInfo Add(ulong address, int size, string namespaceAndTypeName, string name, string signature) + { + var method = new MethodInfo(address, size, namespaceAndTypeName, name, signature); + _methods.Add(method); + return method; + } + + public string GetFullName(ulong address) + { + if (_cache.TryGetValue(address, out var fullName)) + return fullName; + + // look for managed methods + for (int i = 0; i < _methods.Count; i++) + { + var method = _methods[i]; + + if ((address >= method.StartAddress) && (address < method.StartAddress + (ulong)method.Size)) + { + fullName = method.FullName; + _cache[address] = fullName; + return fullName; + } + } + + // look for native methods + fullName = GetNativeMethodName(address); + _cache[address] = fullName; + + return fullName; + } + + private string GetNativeMethodName(ulong address) + { + var symbol = new NativeDbgHelp.SYMBOL_INFO(); + symbol.MaxNameLen = 1024; + symbol.SizeOfStruct = (uint)Marshal.SizeOf(symbol) - 1024; // char buffer is not counted + // the ANSI version of SymFromAddr is called so each character is 1 byte long + + if (NativeDbgHelp.SymFromAddr(_hProcess, address, out var displacement, ref symbol)) + { + var buffer = new StringBuilder(symbol.Name.Length); + + // remove weird "$##" at the end of some symbols + var pos = symbol.Name.LastIndexOf("$##"); + if (pos == -1) + buffer.Append(symbol.Name); + else + buffer.Append(symbol.Name, 0, pos); + + // add offset if any + if (displacement != 0) + buffer.Append($"+0x{displacement}"); + + return buffer.ToString(); + } + + // default value is just the address in HEX +#if DEBUG + return ($"0x{address:x} (SymFromAddr failed with 0x{Marshal.GetLastWin32Error():x})"); +#else + return $"0x{address:x}"; +#endif + + } + + const int ERROR_SUCCESS = 0; + public void AddModule(string filename, ulong baseOfDll, int sizeOfDll) + { + var baseAddress = NativeDbgHelp.SymLoadModule64(_hProcess, IntPtr.Zero, filename, null, baseOfDll, (uint)sizeOfDll); + if (baseAddress == 0) + { + // should work if the same module is added more than once + if (Marshal.GetLastWin32Error() == ERROR_SUCCESS) return; + + Console.WriteLine($"SymLoadModule64 failed for {filename}"); + } + } + + public void Dispose() + { + if (_hProcess == IntPtr.Zero) + return; + _hProcess = IntPtr.Zero; + + _process.Dispose(); + } + } + + internal static class NativeDbgHelp + { + // from C:\Program Files (x86)\Windows Kits\10\Debuggers\inc\dbghelp.h + public const uint SYMOPT_UNDNAME = 0x00000002; + public const uint SYMOPT_DEFERRED_LOADS = 0x00000004; + + [StructLayout(LayoutKind.Sequential)] + public struct SYMBOL_INFO + { + public uint SizeOfStruct; + public uint TypeIndex; // Type Index of symbol + private ulong Reserved1; + private ulong Reserved2; + public uint Index; + public uint Size; + public ulong ModBase; // Base Address of module containing this symbol + public uint Flags; + public ulong Value; // Value of symbol, ValuePresent should be 1 + public ulong Address; // Address of symbol including base address of module + public uint Register; // register holding value or pointer to value + public uint Scope; // scope of the symbol + public uint Tag; // pdb classification + public uint NameLen; // Actual length of name + public uint MaxNameLen; + [MarshalAs(UnmanagedType.ByValTStr, SizeConst = 1024)] + public string Name; + } + + [DllImport("dbghelp.dll", SetLastError = true)] + public static extern bool SymInitialize(IntPtr hProcess, string userSearchPath, bool invadeProcess); + + [DllImport("dbghelp.dll", SetLastError = true)] + public static extern uint SymSetOptions(uint symOptions); + + [DllImport("dbghelp.dll", SetLastError = true, CharSet = CharSet.Ansi)] + public static extern ulong SymLoadModule64(IntPtr hProcess, IntPtr hFile, string imageName, string moduleName, ulong baseOfDll, uint sizeOfDll); + + // use ANSI version to ensure the right size of the structure + // read https://docs.microsoft.com/en-us/windows/win32/api/dbghelp/ns-dbghelp-symbol_info + [DllImport("dbghelp.dll", SetLastError = true, CharSet = CharSet.Ansi)] + public static extern bool SymFromAddr(IntPtr hProcess, ulong address, out ulong displacement, ref SYMBOL_INFO symbol); + + [DllImport("dbghelp.dll", SetLastError = true)] + public static extern bool SymCleanup(IntPtr hProcess); + } +} diff --git a/prof/PerProcessProfilingState.cs b/prof/PerProcessProfilingState.cs new file mode 100644 index 0000000..0ffa72d --- /dev/null +++ b/prof/PerProcessProfilingState.cs @@ -0,0 +1,32 @@ +using ProfilerHelpers; +using System; +using System.Collections.Generic; + +namespace Tracing +{ + public class PerProcessProfilingState : IDisposable + { + private bool _disposed; + + private readonly Dictionary _processNames = new Dictionary(); + private readonly Dictionary _perProcessTypes = new Dictionary(); + private readonly Dictionary _perProcessAllocations = new Dictionary(); + private readonly Dictionary _methods = new Dictionary(); + + public Dictionary Names => _processNames; + public Dictionary Types => _perProcessTypes; + public Dictionary Allocations => _perProcessAllocations; + public Dictionary Methods => _methods; + + public void Dispose() + { + if (_disposed) return; + _disposed = true; + + foreach (var methodStore in _methods.Values) + { + methodStore.Dispose(); + } + } + } +} diff --git a/prof/ProcessAllocations.cs b/prof/ProcessAllocations.cs new file mode 100644 index 0000000..02ae0a9 --- /dev/null +++ b/prof/ProcessAllocations.cs @@ -0,0 +1,130 @@ +using System; +using System.Collections.Generic; + +namespace Tracing +{ + + public class ProcessAllocations + { + private readonly int _pid; + private readonly Dictionary _allocations; + private readonly Dictionary _perThreadLastAllocation; + + public ProcessAllocations(int pid) + { + _pid = pid; + _allocations = new Dictionary(); + _perThreadLastAllocation = new Dictionary(); + } + + public int Pid => _pid; + + public AllocationInfo GetAllocations(string typeName) + { + return (_allocations.TryGetValue(typeName, out var info)) ? info : null; + } + + public IEnumerable GetAllAllocations() + { + return _allocations.Values; + } + + public AllocationInfo AddAllocation(int threadID, ulong size, ulong count, string typeName) + { + if (!_allocations.TryGetValue(typeName, out var info)) + { + info = new AllocationInfo(typeName); + _allocations[typeName] = info; + } + + info.AddAllocation(size, count); + + // the last allocation is still here without the corresponding stack + if (_perThreadLastAllocation.TryGetValue(threadID, out var lastAlloc)) + { + Console.WriteLine("no stack for the last allocation"); + } + + // keep track of the allocation for the given thread + // --> will be used when the corresponding call stack event will be received + _perThreadLastAllocation[threadID] = info; + + return info; + } + + public void AddStack(int threadID, AddressStack stack) + { + if (_perThreadLastAllocation.TryGetValue(threadID, out var lastAlloc)) + { + lastAlloc.AddStack(stack); + _perThreadLastAllocation.Remove(threadID); + return; + } + + //Console.WriteLine("no last allocation for the stack event"); + } + } + + + public class AllocationInfo + { + private readonly string _typeName; + private ulong _size; + private ulong _count; + private List _stacks; + + internal AllocationInfo(string typeName) + { + _typeName = typeName; + _stacks = new List(); + } + + public string TypeName => _typeName; + public ulong Count => _count; + public ulong Size => _size; + public IReadOnlyList Stacks => _stacks; + + internal void AddAllocation(ulong size, ulong count) + { + _count += count; + _size += size; + } + + internal void AddStack(AddressStack stack) + { + var info = GetInfo(stack); + if (info == null) + { + info = new StackInfo(stack); + _stacks.Add(info); + } + + info.Count++; + } + + private StackInfo GetInfo(AddressStack stack) + { + for (int i = 0; i < _stacks.Count; i++) + { + var info = _stacks[i]; + if (stack.Equals(info.Stack)) return info; + } + + return null; + } + } + + public class StackInfo + { + private readonly AddressStack _stack; + public ulong Count; + + internal StackInfo(AddressStack stack) + { + Count = 0; + _stack = stack; + } + + public AddressStack Stack => _stack; + } +} diff --git a/prof/ProcessTypeMapping.cs b/prof/ProcessTypeMapping.cs new file mode 100644 index 0000000..136cad6 --- /dev/null +++ b/prof/ProcessTypeMapping.cs @@ -0,0 +1,35 @@ +using System.Collections.Generic; + +namespace Tracing +{ + // Contains the mapping between type ID received by SampleObjectAllocation(Low/High) events + // and their name received by TypeBulkType events + public class ProcessTypeMapping + { + private readonly Dictionary _typesIdToName; + + public ProcessTypeMapping(int processId) + { + ProcessId = processId; + _typesIdToName = new Dictionary(); + } + + public int ProcessId { get; set; } + + public string this[ulong id] + { + get + { + if (!_typesIdToName.ContainsKey(id)) + return null; + + return _typesIdToName[id]; + } + set + { + _typesIdToName[id] = value; + } + } + + } +} diff --git a/prof/Program.cs b/prof/Program.cs new file mode 100644 index 0000000..e6ae889 --- /dev/null +++ b/prof/Program.cs @@ -0,0 +1,162 @@ +using Microsoft.Diagnostics.Tracing.Session; +using ProfilerHelpers; +using System; +using System.Collections.Generic; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; + +namespace Tracing +{ + static class Program + { + + + static public async Task CreateTracingSession( bool noSampling, bool sortBySize, int topTypesLimit ) + { + ShowHeader(); + + try + { + + TraceEventSession session = new TraceEventSession( + "Tracing", + TraceEventSessionOptions.Create + ); + + log.info( $"Create PerProcessProfilingState" ); + + using( var processes = new PerProcessProfilingState() ) + { + log.info( $"Create Memory profiler for session" ); + var profiler = new Memory( session, processes ); + + log.info( $"Start task" ); + var task = profiler.StartAsync( noSampling ); + + /* + log.info( $"await the Continue" ); + await task.ContinueWith( ( t ) => { + log.info( $"Task is done, Dispose" ); + session.Dispose(); + } ); + */ + + //log.info("Press ENTER to stop memory profiling"); + //Console.ReadLine(); + + /* + try + { + await task; + ShowResults( processes, sortBySize, topTypesLimit ); + + return 0; + } + catch( Exception x ) + { + log.info( x.Message ); + ShowHelp(); + } + */ + } + + return -1; + } + catch( Exception x ) + { + log.info( x.Message ); + ShowHelp(); + } + + return -2; + } + + private static void ShowResults( PerProcessProfilingState processes, bool sortBySize, int topTypesLimit ) + { + foreach( var pid in processes.Allocations.Keys ) + { + // skip processes without symbol resolution + if( !processes.Methods.ContainsKey( pid ) ) + continue; + + // skip processes without allocations + if( !processes.Allocations[pid].GetAllAllocations().Any() ) + continue; + + ShowResults( GetProcessName( pid, processes.Names ), processes.Methods[pid], processes.Allocations[pid], sortBySize, topTypesLimit ); + } + } + + private static string GetProcessName( int pid, Dictionary names ) + { + if( names.TryGetValue( pid, out var name ) ) + return name; + + return pid.ToString(); + } + + private static void ShowResults( string name, MethodStore methods, ProcessAllocations allocations, bool sortBySize, int topTypesLimit ) + { + log.info( $"Memory allocations for {name}" ); + log.info( $"" ); + log.info( "---------------------------------------------------------" ); + log.info( " Count Size Type" ); + log.info( "---------------------------------------------------------" ); + IEnumerable types = ( sortBySize ) + ? allocations.GetAllAllocations().OrderByDescending( a => a.Size ) + : allocations.GetAllAllocations().OrderByDescending( a => a.Count ) + ; + if( topTypesLimit != -1 ) + types = types.Take( topTypesLimit ); + + foreach( var allocation in types ) + { + log.info( $"{allocation.Count,9} {allocation.Size,11} {allocation.TypeName}" ); + + log.info( $"" ); + DumpStacks( allocation, methods ); + log.info( $"" ); + } + log.info( $"" ); + log.info( $"" ); + } + + private static void DumpStacks( AllocationInfo allocation, MethodStore methods ) + { + var stacks = allocation.Stacks.OrderByDescending( s => s.Count ).Take( 10 ); + foreach( var stack in stacks ) + { + log.info( $"{stack.Count,6} allocations" ); + log.info( "----------------------------------" ); + DumpStack( stack.Stack, methods ); + log.info( $"" ); + } + } + + private static void DumpStack( AddressStack stack, MethodStore methods ) + { + var callstack = stack.Stack; + for( int i = 0; i < Math.Min( 10, callstack.Count ); i++ ) + { + log.info( $" {methods.GetFullName( callstack[i] )}" ); + } + } + + private static void ShowHeader() + { + log.info( "Tracing v1.0.0 - Sampled memory profiler for .NET applications" ); + log.info( "by Christophe Nasarre" ); + log.info( $"" ); + } + private static void ShowHelp() + { + log.info( $"" ); + log.info( "Tracing shows sampled allocations of a given .NET application." ); + log.info( "Usage: Tracing [-a (all allocations)] [-c (sort by count instead of default by size)] [-t ]" ); + log.info( " Ex: Tracing -t -1 (all types sampled allocations sorted by size)" ); + log.info( " Ex: Tracing -c -t 10 (allocations for top 10 types sorted by count)" ); + log.info( $"" ); + } + } +} diff --git a/reflect/refl.cs b/reflect/refl.cs index da1168d..348447e 100644 --- a/reflect/refl.cs +++ b/reflect/refl.cs @@ -196,6 +196,8 @@ static public class refl return first; } + LogGC.RegisterObjectId( t ); + lock( t ) { if( s_fieldCache.TryGetValue( t, out var second ) ) diff --git a/res/Resource.cs b/res/Resource.cs index 6d9f08f..dd21884 100644 --- a/res/Resource.cs +++ b/res/Resource.cs @@ -348,7 +348,7 @@ public class Mgr static public T actualLoad( string filename ) where T : class, new() { - lock(s_loading) + lock(s_loadingLock) { if( s_loading.TryGetValue( filename, out var evt ) ) { @@ -412,6 +412,8 @@ public class Mgr m_deferredLoader = new Thread( ts ); + LogGC.RegisterObjectId( s_loadingLock ); + m_deferredLoader.Start(); }