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

BIG fix to logging

Browse Source 
Started using Blocking datastructures making things a lot better.  Thanks Gemini!
This commit is contained in:
Marc Hernandez 2025-09-24 20:56:02 -07:00
parent 83ef5dad91
commit 4b53686b92
3 changed files with 152 additions and 211 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

102
imm/Imm.cs
View File

@ -30,9 +30,9 @@ public interface Obj
/// </summary> /// </summary>
Obj Record( Obj Record(
string reason = "Recorded", string reason = "Recorded",
[CallerMemberName] string memberName = "", [CallerMemberName] string dbgName = "",
[CallerFilePath] string filePath = "", [CallerFilePath] string dbgPath = "",
[CallerLineNumber] int lineNumber = 0 ); [CallerLineNumber] int dbgLine = 0 );
} }
@ -59,9 +59,9 @@ public interface Obj<T> : Obj where T : Obj<T>
T Process( T Process(
Func<T, T> fn, Func<T, T> fn,
string reason = "Processed", string reason = "Processed",
[CallerMemberName] string memberName = "", [CallerMemberName] string dbgName = "",
[CallerFilePath] string filePath = "", [CallerFilePath] string dbgPath = "",
[CallerLineNumber] int lineNumber = 0 , [CallerLineNumber] int dbgLine = 0 ,
[CallerArgumentExpression("fn")] string expStr = "" ); [CallerArgumentExpression("fn")] string expStr = "" );
@ -71,9 +71,9 @@ public interface Obj<T> : Obj where T : Obj<T>
/// </summary> /// </summary>
new T Record( new T Record(
string reason = "Recorded", string reason = "Recorded",
[CallerMemberName] string memberName = "", [CallerMemberName] string dbgName = "",
[CallerFilePath] string filePath = "", [CallerFilePath] string dbgPath = "",
[CallerLineNumber] int lineNumber = 0 ); [CallerLineNumber] int dbgLine = 0 );
} }
@ -186,9 +186,9 @@ public record class Versioned<T> : Obj<T> where T : Versioned<T>
public virtual T Process( public virtual T Process(
Func<T, T> fn, Func<T, T> fn,
string reason = "Processed", string reason = "Processed",
[CallerMemberName] string memberName = "", [CallerMemberName] string dbgName = "",
[CallerFilePath] string filePath = "", [CallerFilePath] string dbgPath = "",
[CallerLineNumber] int lineNumber = 0 , [CallerLineNumber] int dbgLine = 0 ,
[CallerArgumentExpression("fn")] string expStr = "" ) [CallerArgumentExpression("fn")] string expStr = "" )
{ {
var current = (T)this; var current = (T)this;
@ -211,18 +211,18 @@ public record class Versioned<T> : Obj<T> where T : Versioned<T>
/// </summary> /// </summary>
public virtual T Record( public virtual T Record(
string reason = "Recorded", string reason = "Recorded",
[CallerMemberName] string memberName = "", [CallerMemberName] string dbgName = "",
[CallerFilePath] string filePath = "", [CallerFilePath] string dbgPath = "",
[CallerLineNumber] int lineNumber = 0 ) => Process( t => t, reason, memberName, filePath, lineNumber ); [CallerLineNumber] int dbgLine = 0 ) => Process( t => t, reason, dbgName, dbgPath, dbgLine );
/// <summary> /// <summary>
/// Implements Obj.Record by calling the virtual T Record. /// Implements Obj.Record by calling the virtual T Record.
/// </summary> /// </summary>
Obj Obj.Record( Obj Obj.Record(
string reason = "Recorded", string reason = "Recorded",
[CallerMemberName] string memberName = "", [CallerMemberName] string dbgName = "",
[CallerFilePath] string filePath = "", [CallerFilePath] string dbgPath = "",
[CallerLineNumber] int lineNumber = 0 ) => this.Record( reason, memberName, filePath, lineNumber ); [CallerLineNumber] int dbgLine = 0 ) => this.Record( reason, dbgName, dbgPath, dbgLine );
} }
@ -244,9 +244,9 @@ public record class Recorded<T> : Versioned<T> where T : Recorded<T>
public virtual T Process( public virtual T Process(
Func<T, T> fn, Func<T, T> fn,
string reason = "", string reason = "",
[CallerMemberName] string memberName = "", [CallerMemberName] string dbgName = "",
[CallerFilePath] string filePath = "", [CallerFilePath] string dbgPath = "",
[CallerLineNumber] int lineNumber = 0, [CallerLineNumber] int dbgLine = 0,
[CallerArgumentExpression("fn")] string expStr = "") [CallerArgumentExpression("fn")] string expStr = "")
{ {
var current = (T)this; var current = (T)this;
@ -258,9 +258,9 @@ public record class Recorded<T> : Versioned<T> where T : Recorded<T>
{ {
Version = current.Meta.Version + 1, Version = current.Meta.Version + 1,
Reason = reason, Reason = reason,
MemberName = memberName, MemberName = dbgName,
FilePath = filePath, FilePath = dbgPath,
LineNumber = lineNumber, LineNumber = dbgLine,
Expression = expStr, Expression = expStr,
OldObject = current OldObject = current
}; };
@ -272,11 +272,11 @@ public record class Recorded<T> : Versioned<T> where T : Recorded<T>
public new T Record( public new T Record(
string reason = "Recorded", string reason = "Recorded",
[CallerMemberName] string memberName = "", [CallerMemberName] string dbgName = "",
[CallerFilePath] string filePath = "", [CallerFilePath] string dbgPath = "",
[CallerLineNumber] int lineNumber = 0) [CallerLineNumber] int dbgLine = 0)
{ {
return Process(t => t, reason, memberName, filePath, lineNumber ); return Process(t => t, reason, dbgName, dbgPath, dbgLine );
} }
} }
@ -294,27 +294,29 @@ public record class Timed<T> : Recorded<T> where T : Timed<T>
public Timed() { } public Timed() { }
protected Timed(Timed<T> original) : base(original) { Meta = original.Meta; } protected Timed(Timed<T> original) : base(original) { Meta = original.Meta; }
public override T Process( public override T Process(
Func<T, T> fn, Func<T, T> fn,
string reason = "", string reason = "",
[CallerMemberName] string memberName = "", [CallerMemberName] string dbgName = "",
[CallerFilePath] string filePath = "", [CallerFilePath] string dbgPath = "",
[CallerLineNumber] int lineNumber = 0, [CallerLineNumber] int dbgLine = 0,
[CallerArgumentExpression("fn")] string expression = "") [CallerArgumentExpression( "fn" )] string dbgExpression = "" )
{ {
var current = (T)this; var current = (T)this;
var next = fn( current ); var next = fn( current );
if (ReferenceEquals(current, next)) return current; if( ReferenceEquals( current, next ) )
return current;
var newMeta = new Metadata_Timed var newMeta = new Metadata_Timed
{ {
Version = current.Meta.Version + 1, Version = current.Meta.Version + 1,
Reason = reason, Reason = reason,
MemberName = memberName, MemberName = dbgName,
FilePath = filePath, FilePath = dbgPath,
LineNumber = lineNumber, LineNumber = dbgLine,
Expression = expression, Expression = dbgExpression,
OldObject = current, OldObject = current,
CreatedAt = DateTime.UtcNow, CreatedAt = DateTime.UtcNow,
TouchedAt = DateTime.UtcNow TouchedAt = DateTime.UtcNow
@ -328,10 +330,28 @@ public record class Timed<T> : Recorded<T> where T : Timed<T>
public new T Record( public new T Record(
string reason = "Recorded", string reason = "Recorded",
[CallerMemberName] string memberName = "", [CallerMemberName] string dbgName = "",
[CallerFilePath] string filePath = "", [CallerFilePath] string dbgPath = "",
[CallerLineNumber] int lineNumber = 0) [CallerLineNumber] int dbgLine = 0)
{ {
return Process(t => t, reason, memberName, filePath, lineNumber ); return Process(t => t, reason, dbgName, dbgPath, dbgLine );
}
}
public static class TimedExt
{
public static T Process<T>(
ref T obj,
Func<T, T> fn,
string reason = "",
[CallerMemberName] string dbgName = "",
[CallerFilePath] string dbgPath = "",
[CallerLineNumber] int dbgLine = 0,
[CallerArgumentExpression( "fn" )] string dbgExpression = ""
)
where T : imm.Timed<T>
{
obj = obj.Process( fn, reason, dbgName, dbgPath, dbgLine, dbgExpression );
return obj;
} }
} }

2
imm/iu.cs
View File

@ -42,6 +42,8 @@ public static class iu
return obj; return obj;
} }
// No specific Process needed for Timed, as it's caught by Recorded<T> // No specific Process needed for Timed, as it's caught by Recorded<T>
// and its Process override handles the timing. // and its Process override handles the timing.
} }

201
logging/Log.cs
View File

@ -27,7 +27,7 @@ ref: https://learn.microsoft.com/en-us/dotnet/csharp/whats-new/tutorials/interpo
D O N E: D O N E:
N O T D O I N G : N O T  D O I N G :
*/ */
@ -134,22 +134,17 @@ static public class log
static void StartGCWatcher() static void StartGCWatcher()
{ {
while( s_threading != ThreadState.Running ) // This wait is no longer needed with BlockingCollection, but kept for this component's logic
{ // It would be better to use a ManualResetEvent here if waiting is truly needed.
Thread.Sleep( 10 ); Thread.Sleep( 500 ); // Simple wait
}
var processId = Process.GetCurrentProcess().Id; var processId = Process.GetCurrentProcess().Id;
LogGC.PrintRuntimeGCEvents( processId ); LogGC.PrintRuntimeGCEvents( processId );
} }
static void StartTracing() static void StartTracing()
{ {
while( s_threading != ThreadState.Running ) // See above comment
{ Thread.Sleep( 500 );
Thread.Sleep( 10 );
}
Tracing.TraceLogMonitor.Run(); Tracing.TraceLogMonitor.Run();
} }
@ -247,6 +242,7 @@ static public class log
Obj = obj; Obj = obj;
} }
} }
static LogEvent CreateLogEvent( LogType logType, string msg, string cat, object? obj, [CallerFilePath] string path = "", [CallerLineNumber] int line = -1, [CallerMemberName] string member = "", string exp = "" ) static LogEvent CreateLogEvent( LogType logType, string msg, string cat, object? obj, [CallerFilePath] string path = "", [CallerLineNumber] int line = -1, [CallerMemberName] string member = "", string exp = "" )
{ {
var logEvent = new LogEvent( logType, msg, path, line, member, cat, exp, obj ); var logEvent = new LogEvent( logType, msg, path, line, member, cat, exp, obj );
@ -265,25 +261,19 @@ static public class log
static public void create( string filename, Endpoints endpoints )
{
startup( filename, endpoints );
}
static public void shutdown() static public void shutdown()
{ {
string msg = "==============================================================================\nLogfile shutdown at " + DateTime.Now.ToString(); string msg = "==============================================================================\nLogfile shutdown at " + DateTime.Now.ToString();
var evt = CreateLogEvent( LogType.Info, msg, "System", null ); var evt = CreateLogEvent( LogType.Info, msg, "System", null );
s_events.Add( evt ); // Use Add instead of Enqueue
s_events.Enqueue( evt );
stop(); stop();
} }
static internal ConcurrentQueue<LogEvent> s_events = new ConcurrentQueue<LogEvent>(); // MODIFIED: Replaced ConcurrentQueue with BlockingCollection for a more robust producer-consumer pattern.
static readonly BlockingCollection<LogEvent> s_events = new BlockingCollection<LogEvent>( new ConcurrentQueue<LogEvent>() );
static private Thread s_thread = Thread.CurrentThread; static private Thread? s_thread;
static string s_cwd = Directory.GetCurrentDirectory(); static string s_cwd = Directory.GetCurrentDirectory();
static int s_cwdLength = s_cwd.Length; static int s_cwdLength = s_cwd.Length;
@ -407,19 +397,6 @@ static public class log
static public void inf_valueo<A>( string msg, Value<A> v1, string cat = "" )
{
}
static public void info<A>( string msg, A a, string cat = "", [CallerArgumentExpression( "a" )] string dbgExpA = "" )
{
}
static public void info( string msg, object a, object b, string cat = "", [CallerArgumentExpression( "a" )] string dbgExpA = "", [CallerArgumentExpression( "a" )] string dbgExpB = "" )
{
}
#endregion #endregion
#region Helpers #region Helpers
@ -431,8 +408,8 @@ static public class log
{ {
var evt = new LogEvent( type, header, path, line, member, cat, dbgExpObj, obj ); var evt = new LogEvent( type, header, path, line, member, cat, dbgExpObj, obj );
{ {
// Use Add instead of Enqueue
s_events.Enqueue( evt ); s_events.Add( evt );
foreach( var pi in list ) foreach( var pi in list )
{ {
@ -505,7 +482,8 @@ static public class log
} }
else else
{ {
s_events.Enqueue( evt ); // MODIFIED: Use Add instead of Enqueue for the BlockingCollection.
s_events.Add( evt );
} }
@ -515,6 +493,7 @@ static public class log
static Endpoints s_endpoints = Endpoints.Console; static Endpoints s_endpoints = Endpoints.Console;
static int s_catWidth = 14; static int s_catWidth = 14;
static public bool IsLogging => s_thread != null && s_thread.IsAlive;
static public void startup( string filename, Endpoints endpoints ) static public void startup( string filename, Endpoints endpoints )
{ {
@ -525,15 +504,13 @@ static public class log
lock( s_lock ) lock( s_lock )
{ {
//We're already running, so just tell folks, and jump back //We're already running if the thread is alive
if( s_threading == ThreadState.Running ) if( s_thread != null && s_thread.IsAlive )
{ {
log.info( $"Already running, so this is a NOP" ); log.info( $"Already running, so this is a NOP" );
return;
} }
s_threading = ThreadState.Running;
s_startTime = DateTime.Now; s_startTime = DateTime.Now;
s_cwd = Directory.GetCurrentDirectory(); s_cwd = Directory.GetCurrentDirectory();
@ -562,54 +539,29 @@ static public class log
var beginLine = new LogEvent( LogType.Raw, $"Begin B E G I N ******************************************************************************************************************", "", 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 ); 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 );
// MODIFIED: All writes are now safely enqueued to be processed by the logger thread.
// This prevents the StreamWriter buffer corruption that caused null bytes.
//writeToAll( endLine ); s_events.Add( blankLine );
writeToAll( blankLine ); s_events.Add( blankLine );
writeToAll( blankLine ); s_events.Add( beginLine );
writeToAll( beginLine ); s_events.Add( blankLine );
writeToAll( blankLine ); s_events.Add( timeLine );
writeToAll( timeLine ); s_events.Add( blankLine );
writeToAll( blankLine );
} }
LogEvent msgStartupBegin = new LogEvent( LogType.Info, $"startup BEGIN", "", 0, "", "log.startup", "", null ); LogEvent msgStartupBegin = new LogEvent( LogType.Info, $"startup BEGIN", "", 0, "", "log.startup", "", null );
writeToAll( msgStartupBegin ); s_events.Add( msgStartupBegin );
LogEvent msgFilename = new LogEvent( LogType.Info, $"Logging in {filename}", "", 0, "", "log.startup", "", null ); LogEvent msgFilename = new LogEvent( LogType.Info, $"Logging in {filename}", "", 0, "", "log.startup", "", null );
writeToAll( msgFilename ); s_events.Add( msgFilename );
var optionsLine = new LogEvent( LogType.Info, $"Endpoints: {endpoints}", "", 0, "", "log.startup", "", null ); var optionsLine = new LogEvent( LogType.Info, $"Endpoints: {endpoints}", "", 0, "", "log.startup", "", null );
writeToAll( optionsLine ); s_events.Add( optionsLine );
StartThread(); StartThread();
//info( $"Logging in {filename}" );
LogGC.RegisterObjectId( s_lock ); LogGC.RegisterObjectId( s_lock );
//Debug.Listeners.Add( this );
//var evt = CreateLogEvent( LogType.Info, $"startup", "System", null );
//s_events.Enqueue( evt );
/*
if( (endpoints & Endpoints.Console) == Endpoints.Console )
{
addDelegate(WriteToConsole);
}
*/
//LogEvent msgStartupBegin = new LogEvent( LogType.Info, $"startup END", "", 0, "", "lib.time", "", null );
//writeToAll( msgStartupBegin );
info( $"startup END", cat: "log.startup" ); info( $"startup END", cat: "log.startup" );
} }
@ -622,97 +574,64 @@ static public class log
s_thread = new Thread( start ); s_thread = new Thread( start );
s_thread.Priority = ThreadPriority.BelowNormal; s_thread.Priority = ThreadPriority.BelowNormal;
s_thread.Name = $"Logging"; s_thread.Name = $"Logging";
s_thread.IsBackground = true; // Mark as background thread
s_thread.Start(); s_thread.Start();
} }
private static void StopThread( ThreadState thread ) // REMOVED: ThreadState enum, StopThread, pauseThread, and unpauseThread methods.
{ // They are replaced by the simpler, safer lifecycle management of BlockingCollection.
log.info( $"Setting thread to {thread}");
s_threading = thread;
int count = 0;
while( s_thread.IsAlive )
{
Thread.Sleep( 0 );
count++;
}
Console.WriteLine( $"Waited {count} loops" );
}
public enum ThreadState
{
Invalid,
Running,
Paused,
Finished,
}
static ThreadState s_threading = ThreadState.Invalid;
// MODIFIED: Complete rewrite of the thread loop.
// This is now an efficient, blocking loop that consumes zero CPU while waiting for messages.
// It is also free of race conditions.
static void threadLoop() static void threadLoop()
{ {
Console.WriteLine( $"**********************************************************\n" ); Console.WriteLine( $"**********************************************************\n" );
Console.WriteLine( $"Thread started" ); Console.WriteLine( $"Logger thread started" );
log.info( $"Thread started" ); try
while( s_threading != ThreadState.Running )
{ {
// TODO PERF Replace this with a semaphore/mutex // This loop will block when the collection is empty and will
Thread.Sleep( 1 ); // automatically finish when s_events.CompleteAdding() is called from another thread.
} foreach( var evt in s_events.GetConsumingEnumerable() )
while( s_threading == ThreadState.Running )
{
while( s_events.TryDequeue( out var evt ) )
{ {
writeToAll( evt ); writeToAll( evt );
} }
}
// TODO PERF Replace this with a semaphore/mutex catch( Exception ex )
Thread.Sleep( 1 ); {
Console.WriteLine( $"[CRITICAL] Logger thread crashed: {ex}" );
} }
//var endLine = new LogEvent( LogType.Raw, $"End E N D ******************************************************************************************************************", "", 0, "", "lib.time", "", null ); Console.WriteLine( $"Logger thread has finished processing and is shutting down." );
var endLine = new LogEvent( LogType.Raw, $"Thread state {s_threading} ******************************************************************************************************************", "", 0, "", "lib.time", "", null );
writeToAll( endLine );
} }
public static void stop() public static void stop()
{ {
if( s_threading == ThreadState.Finished ) log.info( "Logger shutdown requested.", "log.system" );
return;
StopThread( ThreadState.Finished ); // MODIFIED: This safely signals the consumer thread to finish.
s_events.CompleteAdding();
while( s_events.Count > 0 )
{
// Wait for the queue to be fully processed.
Thread.Sleep( 10 );
}
// Wait for the thread to finish processing all remaining messages in the queue.
s_thread?.Join( 1000 );
s_thread = null;
s_writer?.Close(); s_writer?.Close();
s_stream?.Close(); s_stream?.Close();
//s_errorWriter?.Close(); //s_errorWriter?.Close();
//s_errorStream?.Close(); //s_errorStream?.Close();
} }
public static void pauseThread()
{
log.info("Pausing thread" );
s_threading = ThreadState.Paused;
StopThread( ThreadState.Paused );
}
public static void unpauseThread()
{
s_threading = ThreadState.Running;
StartThread();
}
static public void addDelegate( Log_delegate cb ) static public void addDelegate( Log_delegate cb )
{ {
s_delegates.Add( cb ); s_delegates.Add( cb );