General/sharplib
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

feat: Add explicit transaction class/ID and split functionality into threaded vs action

Browse Source 
x) Added enum for CommitResults
x) Created interface IID<TS>
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
This commit is contained in:
Marc Hernandez 2024-06-05 15:02:21 -07:00
parent 1fd02d1460
commit 404789d87c
14 changed files with 1956 additions and 242 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

46
db/DB.cs
View File

@ -5,27 +5,28 @@ using static Optional.OptionExtensions;
using static System.Collections.Immutable.ImmutableInterlocked; using static System.Collections.Immutable.ImmutableInterlocked;
/* /*
???? Should we have an explicit transaction class/ID? ???? Should we have an explicit transaction class/ID?
???? Should we split things into threaded vs action ???? Should we split things into threaded vs action
*/ */
namespace db namespace db;
{
public enum CommitResults public enum CommitResults
{ {
Invalid, Invalid,
Perfect, Perfect,
Collisions, Collisions,
} }
public interface IID<TS> public interface IID<TS>
{ {
TS id { get; } TS id { get; }
} }
public class DB<TID, T> where T : IID<TID>
{
object m_lock = new object();
public class DB<TID, T> where T : IID<TID>
{
//Current snapshot of the DB. //Current snapshot of the DB.
ImmutableDictionary<TID, T> m_objs = ImmutableDictionary<TID, T>.Empty; ImmutableDictionary<TID, T> m_objs = ImmutableDictionary<TID, T>.Empty;
@ -34,6 +35,11 @@ namespace db
ImmutableDictionary<TID, T> Objects => m_objs; ImmutableDictionary<TID, T> Objects => m_objs;
public DB()
{
LogGC.RegisterObjectId( m_lock );
}
// @@@@ TODO This returns an entity that can be changing. It should be a lazy instantiated copy // @@@@ TODO This returns an entity that can be changing. It should be a lazy instantiated copy
public Option<T> lookup( TID id ) public Option<T> lookup( TID id )
{ {
@ -140,19 +146,19 @@ namespace db
Option<Tx<TID, T>> m_activeTransaction = Option.None<Tx<TID, T>>(); Option<Tx<TID, T>> m_activeTransaction = Option.None<Tx<TID, T>>();
} }
public enum TxStates public enum TxStates
{ {
Invalid, Invalid,
Running, Running,
Committed, Committed,
} }
//This only works for a single thread //This only works for a single thread
public class Tx<TID, T>: IDisposable where T : IID<TID> public class Tx<TID, T>: IDisposable where T : IID<TID>
{ {
internal ImmutableList<T> Checkouts => m_checkouts; internal ImmutableList<T> Checkouts => m_checkouts;
internal TxStates State => m_state; internal TxStates State => m_state;
internal int Start => m_start; internal int Start => m_start;
@ -216,6 +222,4 @@ namespace db
// New objects created this pass // New objects created this pass
ImmutableList<T> m_adds = ImmutableList<T>.Empty; ImmutableList<T> m_adds = ImmutableList<T>.Empty;
}
} }

330
logging/GC.cs
View File

@ -1,42 +1,109 @@
using lib;
using Microsoft.Diagnostics.NETCore.Client; using Microsoft.Diagnostics.NETCore.Client;
using Microsoft.Diagnostics.Tracing; using Microsoft.Diagnostics.Tracing;
using Microsoft.Diagnostics.Tracing.Etlx; using Microsoft.Diagnostics.Tracing.Etlx;
using Microsoft.Diagnostics.Tracing.EventPipe; using Microsoft.Diagnostics.Tracing.EventPipe;
using Microsoft.Diagnostics.Tracing.Parsers; 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;
using System.Collections.Concurrent;
using System.Collections.Generic; using System.Collections.Generic;
using System.Collections.Immutable; using System.Collections.Immutable;
using System.Diagnostics;
using System.Diagnostics.Tracing; using System.Diagnostics.Tracing;
using System.IO;
using System.Linq;
using System.Runtime.InteropServices;
using System.Runtime.Remoting;
using System.Text; using System.Text;
using System.Threading;
using System.Threading.Tasks;
using System.Xml;
using TraceKeywords = Microsoft.Diagnostics.Tracing.Parsers.ClrTraceEventParser.Keywords; using TraceKeywords = Microsoft.Diagnostics.Tracing.Parsers.ClrTraceEventParser.Keywords;
public class RuntimeGCEventsPrinter public static class LogGCExt
{
public static string MethodInfo( TraceEvent te, string prefix = "Method" )
{
return $"{te.PayloadStringByName($"{prefix}Namespace")}.{te.PayloadStringByName($"{prefix}Name")}{te.PayloadStringByName($"{prefix}Signature")}";
}
public static string Get( this TraceEvent te, string name, string def = "" ) => te.PayloadStringByName( name ) ?? def;
public static T Get<T>( this TraceEvent te, string name, T def = default )
{
var index = te.PayloadIndex( name );
if( index <= 0 ) return default;
var value = te.PayloadValue( index );
if( value.GetType() != typeof(T) )
{
log.warn( $"In {te.ID} Payload {name} is type {value.GetType().FriendlyName()} not {typeof(T).FriendlyName()}" );
return default;
}
return (T)value;
}
}
public class LogGC
{ {
static ImmutableHashSet<string> blacklist; static ImmutableHashSet<string> blacklist;
static ImmutableHashSet<string> stacklist; static ImmutableHashSet<string> stacklist;
static RuntimeGCEventsPrinter() static LogGC()
{ {
blacklist = ImmutableHashSet.Create( blacklist = ImmutableHashSet.Create(
"Method/ILToNativeMap", "FAKE_TEST",
"GC/BulkMovedObjectRanges", "GC/BulkMovedObjectRanges",
/*
"GC/BulkSurvivingObjectRanges", "GC/BulkSurvivingObjectRanges",
"GC/FinalizeObject",
"Type/BulkType",
"GC/SetGCHandle",
"GC/DestoryGCHandle",
"TypeLoad/Start",
"Method/R2RGetEntryPointStart",
"Method/MethodDetails",
"Method/MemoryAllocatedForJitCode",
"Method/JittingStarted",
"GC/BulkRootStaticVar", "GC/BulkRootStaticVar",
"GC/BulkNode", "GC/BulkNode",
"GC/BulkEdge", "GC/BulkEdge",
"GC/BulkRootEdge", "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", "ThreadPoolWorkerThread/Wait",
"ILStub/StubGenerated" "ILStub/StubGenerated"
*/
"FAKE_END_IS_NOTHING"
); );
stacklist = ImmutableHashSet.Create( "{TEST_ITEM}" ); 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<TraceEvent> LogCategoryFunc( string catIn ) public static Action<TraceEvent> LogCategoryFunc( string catIn )
{ {
return ( TraceEvent te ) => return ( TraceEvent te ) =>
@ -63,7 +147,7 @@ public class RuntimeGCEventsPrinter
if( blacklist.Contains( te.EventName )) return; if( blacklist.Contains( te.EventName )) return;
{ {
var methodBeingCompiledNamespace = te.PayloadStringByName("MethodBeingCompiledNamespace") ?? ""; var methodBeingCompiledNamespace = te.Get("MethodBeingCompiledNamespace");
if( ( methodBeingCompiledNamespace.StartsWith( "Microsoft" ) || methodBeingCompiledNamespace.StartsWith( "System" ) ) ) return; if( ( methodBeingCompiledNamespace.StartsWith( "Microsoft" ) || methodBeingCompiledNamespace.StartsWith( "System" ) ) ) return;
} }
@ -78,6 +162,7 @@ public class RuntimeGCEventsPrinter
} }
{ {
var ns = te.PayloadStringByName("TypeLoad/Stop") ?? ""; var ns = te.PayloadStringByName("TypeLoad/Stop") ?? "";
if( ns.StartsWith( "Godot" ) ) return; if( ns.StartsWith( "Godot" ) ) return;
@ -104,40 +189,185 @@ public class RuntimeGCEventsPrinter
// Custom event displays // Custom event displays
if( te.EventName == "Method/LoadVerbose" ) 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; return;
//logDetails = "| Details: "; //logDetails = "| Details: ";
} }
else if( te.EventName.StartsWith( "Method/Inlining" ) ) 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; return;
//logDetails = "| Details: "; //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" ) 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." ) )
log.info( $"{typeName} Level: {te.PayloadStringByName("LoadLevel")}", cat: te.EventName );
return; return;
log.info( $"{typeName} Level: {te.PayloadStringByName( "LoadLevel" )}", cat: te.EventName );
//*/
return;
//logDetails = "| Details: "; //logDetails = "| Details: ";
} }
else if( te.EventName.StartsWith( "Method/R2RGetEntryPoint" ) ) 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; return;
//logDetails = "| Details: "; //logDetails = "| Details: ";
} }
else if( te.EventName.StartsWith( "Contention/LockCreated" ) )
{
// "Contention/Start" AssociatedObjectID
// System.Runtime.InteropServices.GCHandle.FromIntPtr(
//76 CHARACTERS var lockId = te.Get<UInt64>( "LockID" );
//<Event MSec= "180.2315" PID="35297" PName="Process(35297)" TID="294046" var objId = te.Get<UInt64>( "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<UInt64>( "LockID" );
var objId = te.Get<UInt64>( "AssociatedObjectID" );
var threadId = te.Get<Int64>( "LockOwnerThreadID" );
log.info( $"Lock {lockId} {te.Get( "ContentionFlags" )} in thread {threadId} on obj 0x{objId.ToString("X")} ", cat: te.EventName );
LogGeneric( te, "| Raw: " );
}
else if( te.EventName.StartsWith( "Contention/Stop" ) )
{
//var lockId = te.Get<int>( "LockID" );
//var objId = te.Get<IntPtr>( "AssociatedObjectID" );
//var threadId = te.Get<Int64>( "LockOwnerThreadID" );
log.info( $"Lock {{lockId}} {te.Get( "ContentionFlags" )} Duration {te.Get<double>( "DurationNs" )}ns", cat: te.EventName );
LogGeneric( te, "| Raw: " );
}
else if( te.EventName.StartsWith( "AssemblyLoader/" ) || te.EventName.StartsWith( "Loader/" ) )
{
//AssemblyLoader/Start AssemblyName AssemblyLoadContext RequestingAssemblyLoadContext AssemblyPath RequestingAssembly
//AssemblyLoader/Stop AssemblyName AssemblyLoadContext RequestingAssemblyLoadContext AssemblyPath RequestingAssembly Success ResultAssemblyName ResultAssemblyPath Cached
//Loader/AssemblyLoad AssemblyID AppDomainID AssemblyFlags FullyQualifiedAssemblyName BindingID
//AssemblyLoader/ResolutionAttempted
// AssemblyName AssemblyLoadContext Result ResultAssemblyName ResultAssemblyPath Stage ErrorMessage
//Loader/ModuleLoad ModuleID AssemblyID ModuleFlags ModuleILPath ModuleNativePath ManagedPdbSignature ManagedPdbAge ManagedPdbBuildPath
//Loader/DomainModuleLoad ModuleID AssemblyID ModuleFlags ModuleILPath ModuleNativePath AppDomainID
//AssemblyLoader/KnownPathProbed FilePath Source Result
var appDomainId = te.Get( "AppDomainID" );
var asId = te.Get( "AssemblyID" );
var asName = te.Get( "AssemblyName" );
var asPath = te.Get( "AssemblyPath" );
var asLC = te.Get( "AssemblyLoadContext" );
var reqAs = te.Get( "RequestingAssembly" );
var reqAsLC = te.Get( "RequestingAssemblyLoadContext" );
var reqAsName = te.Get( "ResultAssemblyName" );
var reqAsPath = te.Get( "ResultAssemblyPath" );
var success = te.Get( "Success" );
var cached = te.Get( "Cached" );
var errMsg = te.Get( "ErrorMessage" );
var stage = te.Get( "Stage" );
var result = te.Get( "Result" );
var source = te.Get( "Source" );
var modId = te.Get( "ModuleID" );
var modFlags = te.Get( "ModuleFlags" );
var modILPath = te.Get( "ModuleILPath" );
var modNativePath= te.Get( "ModuleNativePath" );
var manBuildPath= te.Get( "ManagedPdbBuildPath" );
var fqaName = te.Get( "FullyQualifiedAssemblyName" );
var bindingId = te.Get( "BindingID" );
}
//76 CHARACTERS
//<Event MSec= "180.2315" PID="35297" PName="Process(35297)" TID="294046"
LogGeneric( te, logDetails );
@ -182,6 +412,42 @@ public class RuntimeGCEventsPrinter
}; };
} }
private static ConcurrentDictionary<string, ImmutableHashSet<string>> s_validKeywords = new();
private static void LogGeneric( TraceEvent te, string logDetails )
{
var teStr = te.ToString().Replace( "ClrInstanceID=\"0\"", "" );
/*
*/
var startIndex = teStr.IndexOf( "EventName" );
//log.debug( $"{logDetails} {startIndex} {teStr}", cat: te.EventName );
var teStrSlice = teStr.AsSpan( startIndex, teStr.Length - ( startIndex + 1 + 1 ) );
log.debug( $"{logDetails}{teStrSlice}", cat: te.EventName );
/*
try
{
TraceCallStack? callstack = te.CallStack();
//if( callstack != null) log.trace( $"| Callstack: {callstack?.ToString()}" );
if( callstack != null )
{
log.trace( $"| Callstack:" );
log.trace( $"| {callstack.Depth}" );
log.trace( $"| {callstack.CodeAddress}" );
}
}
catch( Exception ex )
{
log.debug( $"Caught {ex.Message} while getting the callstack" );
}
//*/
}
public static void PrintRuntimeGCEvents( int processId ) public static void PrintRuntimeGCEvents( int processId )
{ {
@ -211,10 +477,11 @@ public class RuntimeGCEventsPrinter
var source = new EventPipeEventSource( session.EventStream ); 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. // Doesnt seem to be too interesting.
//source.Dynamic.All += LogCategoryFunc( "dynamic" ); //source.Dynamic.All += LogCategoryFunc( "dynamic" );
@ -231,4 +498,9 @@ public class RuntimeGCEventsPrinter
} }
} }
} }
private static void OnAllocTick( GCAllocationTickTraceData data )
{
}
} }

105
logging/Log.cs
View File

@ -77,9 +77,13 @@ public struct SourceLoc
static public class log static public class log
{ {
//static
static log() static log()
{ {
//* log.high( $"Starting tracers" );
/*
{ {
var start = new ThreadStart( StartGCWatcher ); 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 ); var start = new ThreadStart( StartTracing );
@ -112,7 +127,7 @@ static public class log
} }
var processId = Process.GetCurrentProcess().Id; var processId = Process.GetCurrentProcess().Id;
RuntimeGCEventsPrinter.PrintRuntimeGCEvents( processId ); LogGC.PrintRuntimeGCEvents( processId );
} }
static void StartTracing() static void StartTracing()
@ -327,6 +342,27 @@ static public class log
#endregion // Util #endregion // Util
#region Forwards #region Forwards
static public T call<T>( Func<T> 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>( 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 = "" ) 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 ); logBase( msg, LogType.Fatal, path, line, member, cat, dbgExp, obj );
@ -461,13 +497,6 @@ static public class log
s_endpoints = endpoints; 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 ); var dir = Path.GetDirectoryName( filename );
if( dir?.Length > 0 ) if( dir?.Length > 0 )
@ -482,8 +511,43 @@ static public class log
s_errorStream = new FileStream( filename + ".error", FileMode.Append, FileAccess.Write ); s_errorStream = new FileStream( filename + ".error", FileMode.Append, FileAccess.Write );
s_errorWriter = new StreamWriter( s_errorStream ); 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 ); //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() 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 ) while( s_running )
{ {
@ -536,6 +586,7 @@ static public class log
Thread.Sleep( 0 ); Thread.Sleep( 0 );
} }
var endLine = new LogEvent( LogType.Raw, $"End E N D ******************************************************************************************************************", "", 0, "", "lib.time", "", null );
writeToAll( endLine ); writeToAll( endLine );
} }

41
prof/AddressStack.cs Normal file
View File

@ -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<ulong> _stack;
public AddressStack(int capacity)
{
_stack = new List<ulong>(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<ulong> Stack => _stack;
public void AddFrame(ulong address)
{
_stack.Add(address);
}
}
}

314
prof/Memory.cs Normal file
View File

@ -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 );
}
}
}

393
prof/MemoryPipe.cs Normal file
View File

@ -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<EventPipeProvider>()
{
new EventPipeProvider("Microsoft-Windows-DotNETRuntime",
EventLevel.Verbose, (long)(
TraceKeywords.GC |
TraceKeywords.Contention |
TraceKeywords.Debugger |
TraceKeywords.Exception |
TraceKeywords.GCAllObjectAllocation |
TraceKeywords.GCSampledObjectAllocationHigh |
TraceKeywords.GCSampledObjectAllocationLow |
TraceKeywords.Security |
TraceKeywords.Threading |
TraceKeywords.Type |
TraceKeywords.TypeDiagnostic |
TraceKeywords.WaitHandle |
TraceKeywords.All
) )
};
//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 );
}
}
}

68
prof/MethodInfo.cs Normal file
View File

@ -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;
}
}

208
prof/MethodStore.cs Normal file
View File

@ -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<MethodInfo> _methods;
// addresses from callstacks already matching (address -> full name)
private readonly Dictionary<ulong, string> _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<MethodInfo>(1024);
_cache = new Dictionary<ulong, string>();
_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);
}
}

32
prof/PerProcessProfilingState.cs Normal file
View File

@ -0,0 +1,32 @@
using ProfilerHelpers;
using System;
using System.Collections.Generic;
namespace Tracing
{
public class PerProcessProfilingState : IDisposable
{
private bool _disposed;
private readonly Dictionary<int, string> _processNames = new Dictionary<int, string>();
private readonly Dictionary<int, ProcessTypeMapping> _perProcessTypes = new Dictionary<int, ProcessTypeMapping>();
private readonly Dictionary<int, ProcessAllocations> _perProcessAllocations = new Dictionary<int, ProcessAllocations>();
private readonly Dictionary<int, MethodStore> _methods = new Dictionary<int, MethodStore>();
public Dictionary<int, string> Names => _processNames;
public Dictionary<int, ProcessTypeMapping> Types => _perProcessTypes;
public Dictionary<int, ProcessAllocations> Allocations => _perProcessAllocations;
public Dictionary<int, MethodStore> Methods => _methods;
public void Dispose()
{
if (_disposed) return;
_disposed = true;
foreach (var methodStore in _methods.Values)
{
methodStore.Dispose();
}
}
}
}

130
prof/ProcessAllocations.cs Normal file
View File

@ -0,0 +1,130 @@
using System;
using System.Collections.Generic;
namespace Tracing
{
public class ProcessAllocations
{
private readonly int _pid;
private readonly Dictionary<string, AllocationInfo> _allocations;
private readonly Dictionary<int, AllocationInfo> _perThreadLastAllocation;
public ProcessAllocations(int pid)
{
_pid = pid;
_allocations = new Dictionary<string, AllocationInfo>();
_perThreadLastAllocation = new Dictionary<int, AllocationInfo>();
}
public int Pid => _pid;
public AllocationInfo GetAllocations(string typeName)
{
return (_allocations.TryGetValue(typeName, out var info)) ? info : null;
}
public IEnumerable<AllocationInfo> 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<StackInfo> _stacks;
internal AllocationInfo(string typeName)
{
_typeName = typeName;
_stacks = new List<StackInfo>();
}
public string TypeName => _typeName;
public ulong Count => _count;
public ulong Size => _size;
public IReadOnlyList<StackInfo> 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;
}
}

35
prof/ProcessTypeMapping.cs Normal file
View File

@ -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<ulong, string> _typesIdToName;
public ProcessTypeMapping(int processId)
{
ProcessId = processId;
_typesIdToName = new Dictionary<ulong, string>();
}
public int ProcessId { get; set; }
public string this[ulong id]
{
get
{
if (!_typesIdToName.ContainsKey(id))
return null;
return _typesIdToName[id];
}
set
{
_typesIdToName[id] = value;
}
}
}
}

162
prof/Program.cs Normal file
View File

@ -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<int> 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<int, string> 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<AllocationInfo> 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 <type count (instead of 3 types by default)>]" );
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( $"" );
}
}
}

2
reflect/refl.cs
View File

@ -196,6 +196,8 @@ static public class refl
return first; return first;
} }
LogGC.RegisterObjectId( t );
lock( t ) lock( t )
{ {
if( s_fieldCache.TryGetValue( t, out var second ) ) if( s_fieldCache.TryGetValue( t, out var second ) )

4
res/Resource.cs
View File

@ -348,7 +348,7 @@ public class Mgr
static public T actualLoad<T>( string filename ) where T : class, new() static public T actualLoad<T>( string filename ) where T : class, new()
{ {
lock(s_loading) lock(s_loadingLock)
{ {
if( s_loading.TryGetValue( filename, out var evt ) ) if( s_loading.TryGetValue( filename, out var evt ) )
{ {
@ -412,6 +412,8 @@ public class Mgr
m_deferredLoader = new Thread( ts ); m_deferredLoader = new Thread( ts );
LogGC.RegisterObjectId( s_loadingLock );
m_deferredLoader.Start(); m_deferredLoader.Start();
} }