From 404789d87ce14b98e62879b0595981db84fd8a1a Mon Sep 17 00:00:00 2001 From: Marc Hernandez Date: Wed, 5 Jun 2024 15:02:21 -0700 Subject: [PATCH] feat: Add explicit transaction class/ID and split functionality into threaded vs action x) Added enum for CommitResults x) Created interface IID x) Implemented DB class with lock, objects, committed lists x) Updated lookup and checkout methods in DB class x) Added TxStates enum and implemented Tx class with checkout, add, dispose methods x) Implemented commit method in DB class to handle transactions efficiently --- db/DB.cs | 372 ++++++++++++++--------------- logging/GC.cs | 332 +++++++++++++++++++++++--- logging/Log.cs | 105 ++++++--- prof/AddressStack.cs | 41 ++++ prof/Memory.cs | 314 ++++++++++++++++++++++++ prof/MemoryPipe.cs | 393 +++++++++++++++++++++++++++++++ prof/MethodInfo.cs | 68 ++++++ prof/MethodStore.cs | 208 ++++++++++++++++ prof/PerProcessProfilingState.cs | 32 +++ prof/ProcessAllocations.cs | 130 ++++++++++ prof/ProcessTypeMapping.cs | 35 +++ prof/Program.cs | 162 +++++++++++++ reflect/refl.cs | 2 + res/Resource.cs | 4 +- 14 files changed, 1956 insertions(+), 242 deletions(-) create mode 100644 prof/AddressStack.cs create mode 100644 prof/Memory.cs create mode 100644 prof/MemoryPipe.cs create mode 100644 prof/MethodInfo.cs create mode 100644 prof/MethodStore.cs create mode 100644 prof/PerProcessProfilingState.cs create mode 100644 prof/ProcessAllocations.cs create mode 100644 prof/ProcessTypeMapping.cs create mode 100644 prof/Program.cs 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(); }