diff --git a/SharpLib.csproj b/SharpLib.csproj index c726707..9f993c2 100644 --- a/SharpLib.csproj +++ b/SharpLib.csproj @@ -25,9 +25,12 @@ - + - + + + + diff --git a/logging/GC.cs b/logging/GC.cs new file mode 100644 index 0000000..ae5cf4f --- /dev/null +++ b/logging/GC.cs @@ -0,0 +1,53 @@ +using Microsoft.Diagnostics.NETCore.Client; +using Microsoft.Diagnostics.Tracing; +using Microsoft.Diagnostics.Tracing.EventPipe; +using Microsoft.Diagnostics.Tracing.Parsers; +using System; +using System.Collections.Generic; +using System.Collections.Immutable; +using System.Diagnostics.Tracing; + +public class RuntimeGCEventsPrinter +{ + public static void PrintRuntimeGCEvents(int processId) + { + var providers = new List() + { + new EventPipeProvider("Microsoft-Windows-DotNETRuntime", + EventLevel.Informational, (long)ClrTraceEventParser.Keywords.Default) + }; + + var client = new DiagnosticsClient(processId); + using (EventPipeSession session = client.StartEventPipeSession(providers, false)) + { + var source = new EventPipeEventSource(session.EventStream); + + var blacklist = ImmutableHashSet.Create( "Method/ILToNativeMap", "GC/BulkMovedObjectRanges", "GC/BulkSurvivingObjectRanges" ); + + var fnFilter = (TraceEvent te) => { + //Console.WriteLine(obj.ToString()); + if( blacklist.Contains( te.EventName ) ) return; + + log.info( $"{te}", cat: "clr" ); + + }; + + source.Clr.All += fnFilter; + + source.Kernel.All += fnFilter; + + source.Dynamic.All += fnFilter; + + + try + { + source.Process(); + } + catch (Exception e) + { + Console.WriteLine("Error encountered while processing events"); + Console.WriteLine(e.ToString()); + } + } + } +} diff --git a/logging/Log.cs b/logging/Log.cs index ed1eee4..f2efbe6 100644 --- a/logging/Log.cs +++ b/logging/Log.cs @@ -12,6 +12,7 @@ using System.Threading; using System.Security.Cryptography.X509Certificates; using lib.Net; using System.Dynamic; +using System.Xml.Schema; //using System.Threading.Tasks; #nullable enable @@ -20,7 +21,7 @@ using System.Dynamic; T O D O : x) Refactor various logs in order to do automagic structured logging -x) +ref: https://learn.microsoft.com/en-us/dotnet/csharp/whats-new/tutorials/interpolated-string-handler D O N E: @@ -75,6 +76,55 @@ public struct SourceLoc static public class log { + static log() + { + //* + { + var start = new ThreadStart( StartGCWatcher ); + + var thread = new Thread( start ); + thread.Priority = ThreadPriority.BelowNormal; + thread.Name = $"Logging"; + thread.Start(); + } + // */ + + /* + { + var start = new ThreadStart( StartTracing ); + + var thread = new Thread( start ); + thread.Priority = ThreadPriority.BelowNormal; + thread.Name = $"Logging"; + thread.Start(); + } + // */ + + + } + + static void StartGCWatcher() + { + while( !s_running ) + { + Thread.Sleep( 10 ); + } + + var processId = Process.GetCurrentProcess().Id; + RuntimeGCEventsPrinter.PrintRuntimeGCEvents( processId ); + } + + static void StartTracing() + { + while( !s_running ) + { + Thread.Sleep( 10 ); + } + + Tracing.TraceLogMonitor.Run(); + } + + static public Value Value( T val, [CallerArgumentExpression("val")] string dbgExp = "" diff --git a/logging/Tracing.cs b/logging/Tracing.cs new file mode 100644 index 0000000..a7c70f3 --- /dev/null +++ b/logging/Tracing.cs @@ -0,0 +1,301 @@ +using Microsoft.Diagnostics.Symbols; +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 System; +using System.Diagnostics; +using System.IO; +using System.Threading; +using System.Threading.Tasks; + +namespace Tracing +{ + /// + /// This is an example of using the Real-Time (non-file) based support of TraceLog to get stack traces for events. + /// + internal class TraceLogMonitor + { + /// + /// Where all the output goes. + /// + private static TextWriter Out = TextWriter.Null; + + public static void Run() + { + var monitoringTimeSec = 10; + + log.info("******************** RealTimeTraceLog DEMO ********************"); + log.info("This program Shows how to use the real-time support in TraceLog"); + log.info("We do this by showing how to monitor exceptions in real time "); + + log.info("This code depends on a Feature of Windows 8.1 (combined user and kernel sessions)"); + log.info("It will work on Win7 machines, however win7 can have only one kernel session"); + log.info("so it will disrupt any use of the kernel session on that OS. "); + + log.info("Note that this support is currently experimental and subject to change"); + + log.info("Monitoring .NET Module load and Exception events (with stacks)."); + log.info("Run some managed code (ideally that has exceptions) while the monitor is running."); + + + if (Environment.OSVersion.Version.Major * 10 + Environment.OSVersion.Version.Minor < 62) + { + log.info("This demo will preempt any use of the kernel provider. "); + } + + TraceEventSession session = null; + + // Set up Ctrl-C to stop both user mode and kernel mode sessions + Console.CancelKeyPress += (object sender, ConsoleCancelEventArgs cancelArgs) => + { + if (session != null) + { + session.Dispose(); + } + + cancelArgs.Cancel = true; + }; + + /* + // Cause an exception to be thrown a few seconds in (so we have something interesting to look at) + var exceptionGeneationTask = Task.Factory.StartNew(delegate + { + Thread.Sleep(3000); + ThrowException(); + }); + */ + + Timer timer = null; + + // Create the new session to receive the events. + // Because we are on Win 8 this single session can handle both kernel and non-kernel providers. + using (session = new TraceEventSession("TraceLogSession", TraceEventSessionOptions.Attach)) + { + // Enable the events we care about for the kernel + // For this instant the session will buffer any incoming events. + // Enabling kernel events must be done before anything else. + // Note that on Win7 it will turn on the one and only NT Kernel Session, and thus interrupt any kernel session in progress. + // On WIn8 you get a new session (like you would expect). + // + // Note that if you turn on the KernelTraceEventParser.Keywords.Profile, you can also get stacks for CPU sampling + // (every millisecond). (You can use the traceLogSource.Kernel.PerfInfoSample callback). + log.info("Enabling Image load, Process and Thread events. These are needed to look up native method names."); + + try + { + session.EnableKernelProvider( + // KernelTraceEventParser.Keywords.Profile | // If you want CPU sampling events + // KernelTraceEventParser.Keywords.ContextSwitch | // If you want context switch events + // KernelTraceEventParser.Keywords.Thread | // If you want context switch events you also need thread start events. + KernelTraceEventParser.Keywords.ImageLoad | + KernelTraceEventParser.Keywords.Process, /****** The second parameter indicates which kernel events should have stacks *****/ + // KernelTraceEventParser.Keywords.ImageLoad | // If you want Stacks image load (load library) events + // KernelTraceEventParser.Keywords.Profile | // If you want Stacks for CPU sampling events + // KernelTraceEventParser.Keywords.ContextSwitch | // If you want Stacks for context switch events + KernelTraceEventParser.Keywords.None + ); + } + catch( Exception ex ) + { + log.error( $"{ex}" ); + } + + + log.info("Enabling CLR Exception and Load events (and stack for those events)"); + try + { + // We are monitoring exception events (with stacks) and module load events (with stacks) + session.EnableProvider( + ClrTraceEventParser.ProviderGuid, + TraceEventLevel.Informational, + (ulong)(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. + ClrTraceEventParser.Keywords.Exception | // We want to see the exception events. + ClrTraceEventParser.Keywords.Stack)); // And stacks on all CLR events where it makes sense. + + } + catch( Exception ex ) + { + log.error( $"{ex}" ); + } + + log.info("Enabling CLR Events to 'catch up' on JIT compiled code in running processes."); + try + { + // The CLR events turned on above will let you resolve JIT compiled code as long as the JIT compilation + // happens AFTER the session has started. To handle the case for JIT compiled code that was already + // compiled we need to tell the CLR to dump 'Rundown' events for all existing JIT compiled code. We + // do that here. + session.EnableProvider(ClrRundownTraceEventParser.ProviderGuid, TraceEventLevel.Informational, + (ulong)(ClrTraceEventParser.Keywords.Jit | // We need JIT events to be rundown to resolve method names + ClrTraceEventParser.Keywords.JittedMethodILToNativeMap | // This is needed if you want line number information in the stacks + ClrTraceEventParser.Keywords.Loader | // As well as the module load events. + ClrTraceEventParser.Keywords.StartEnumeration)); // This indicates to do the rundown now (at enable time) + + } + catch( Exception ex ) + { + log.error( $"{ex}" ); + } + + + // Because we care about symbols in native code or NGEN images, we need a SymbolReader to decode them. + + // There is a lot of messages associated with looking up symbols, but we don't want to clutter up + // The output by default, so we save it to an internal buffer you can ToString in debug code. + // A real app should make this available somehow to the user, because sooner or later you DO need it. + TextWriter SymbolLookupMessages = new StringWriter(); + // TextWriter SymbolLookupMessages = Out; // If you want the symbol debug spew to go to the output, use this. + + // By default a symbol Reader uses whatever is in the _NT_SYMBOL_PATH variable. However you can override + // if you wish by passing it to the SymbolReader constructor. Since we want this to work even if you + // have not set an _NT_SYMBOL_PATH, so we add the Microsoft default symbol server path to be sure/ + + log.info( $"Loading symbols from {SymbolPath.MicrosoftSymbolServerPath}" ); + var symbolPath = new SymbolPath(SymbolPath.SymbolPathFromEnvironment).Add(SymbolPath.MicrosoftSymbolServerPath); + + + SymbolReader symbolReader = new SymbolReader(SymbolLookupMessages, symbolPath.ToString()); + + // By default the symbol reader will NOT read PDBs from 'unsafe' locations (like next to the EXE) + // because hackers might make malicious PDBs. If you wish ignore this threat, you can override this + // check to always return 'true' for checking that a PDB is 'safe'. + symbolReader.SecurityCheck = (path => true); + + log.info("Open a real time TraceLog session (which understands how to decode stacks)."); + + try + { + using (TraceLogEventSource traceLogSource = TraceLog.CreateFromTraceEventSession(session)) + { + // We use this action in the particular callbacks below. Basically we pass in a symbol reader so we can decode the stack. + // Often the symbol reader is a global variable instead. + Action PrintEvent = ((TraceEvent data) => Print(data, symbolReader)); + + // We will print Exceptions and ModuleLoad events. (with stacks). + traceLogSource.Clr.ExceptionStart += PrintEvent; + traceLogSource.Clr.LoaderModuleLoad += PrintEvent; + // traceLogSource.Clr.All += PrintEvent; + + // If you want to see stacks for various other kernel events, uncomment these (you also need to turn on the events above) + traceLogSource.Kernel.PerfInfoSample += ((SampledProfileTraceData data) => Print(data, symbolReader)); + // traceLogSource.Kernel.ImageLoad += ((ImageLoadTraceData data) => Print(data, symbolReader)); + + // process events until Ctrl-C is pressed or timeout expires + log.info($"Waiting {monitoringTimeSec} sec for Events. Run managed code to see data. "); + log.info("Keep in mind there is a several second buffering delay"); + + // Set up a timer to stop processing after monitoringTimeSec + timer = new Timer(delegate (object state) + { + log.info($"Stopped Monitoring after {monitoringTimeSec} sec"); + if (session != null) + { + session.Dispose(); + } + + session = null; + }, null, monitoringTimeSec * 1000, Timeout.Infinite); + + traceLogSource.Process(); + } + } + catch( Exception ex ) + { + log.error( $"{ex}" ); + } + + + + } + log.info("Finished"); + if (timer != null) + { + timer.Dispose(); // Turn off the timer. + } + } + + /// + /// Print data. Note that this method is called FROM DIFFERNET THREADS which means you need to properly + /// lock any read-write data you access. It turns out log.info is already thread safe so + /// there is nothing I have to do in this case. + /// + private static void Print(TraceEvent data, SymbolReader symbolReader) + { + // There are a lot of data collection start on entry that I don't want to see (but often they are quite handy + if (data.Opcode == TraceEventOpcode.DataCollectionStart) + { + return; + } + // V3.5 runtimes don't log the stack and in fact don't event log the exception name (it shows up as an empty string) + // Just ignore these as they are not that interesting. + if (data is ExceptionTraceData && ((ExceptionTraceData)data).ExceptionType.Length == 0) + { + return; + } + + if (!data.ProcessName.Contains("Samples")) + { + return; + } + + log.info($"EVENT: {data}"); + var callStack = data.CallStack(); + if (callStack != null) + { + // Because symbol lookup is complex, error prone, and expensive TraceLog requires you to be explicit. + // Here we look up names in this call stack using the symbol reader. + ResolveNativeCode(callStack, symbolReader); + log.info($"CALLSTACK: {callStack.ToString()}" ); + } + } + + /// + /// Because it is expensive and often unnecessary, lookup of native symbols needs to be explicitly requested. + /// Here we do this for every frame in the stack. Note that this is not needed for JIT compiled managed code. + /// + private static void ResolveNativeCode(TraceCallStack callStack, SymbolReader symbolReader) + { + while (callStack != null) + { + var codeAddress = callStack.CodeAddress; + if (codeAddress.Method == null) + { + var moduleFile = codeAddress.ModuleFile; + if (moduleFile == null) + { + Trace.WriteLine(string.Format("Could not find module for Address 0x{0:x}", codeAddress.Address)); + } + else + { + codeAddress.CodeAddresses.LookupSymbolsForModule(symbolReader, moduleFile); + } + } + callStack = callStack.Caller; + } + } + + // Force it not to be inlined so we see the stack. + [System.Runtime.CompilerServices.MethodImpl(System.Runtime.CompilerServices.MethodImplOptions.NoInlining)] + private static void ThrowException() + { + ThrowException1(); + } + + // Force it not to be inlined so we see the stack. + [System.Runtime.CompilerServices.MethodImpl(System.Runtime.CompilerServices.MethodImplOptions.NoInlining)] + private static void ThrowException1() + { + log.info("Causing an exception to happen so a CLR Exception Start event will be generated."); + try + { + throw new Exception("This is a test exception thrown to generate a CLR event"); + } + catch (Exception) { } + } + } +}