public void QueueLogWriterCanBeDisposedEarly()
{
var innerLogWriter = new TestLogWriter <MessageEntry>(SetupLog, false);
BackgroundMultiLogWriter backgroundMultiLogWriter;
IQueueEntryWriter <MessageEntry> queueEntryWriter;
SetupBackgroundLogWriter(innerLogWriter, out backgroundMultiLogWriter, out queueEntryWriter);
using (backgroundMultiLogWriter)
{
using (queueEntryWriter as IDisposable)
{
ExampleHelper.LogTestMessagesInParallel(queueEntryWriter, 8, 8, _testOutputHelper);
}
Assert.False(queueEntryWriter.IsEnabled);
Assert.False(queueEntryWriter.IsStarted);
Assert.True(backgroundMultiLogWriter.IsStarted);
// Can't restart after Dispose()
Assert.Throws <ObjectDisposedException>(() => queueEntryWriter.Start());
// Logging still doesn't throw after Dispose
var msg = new MessageEntry("Logged while Dispose()ed - never logged.");
queueEntryWriter.Write(ref msg);
}
Assert.False(backgroundMultiLogWriter.IsStarted);
Assert.False(backgroundMultiLogWriter.IsBackgroundThreadRunning);
Assert.Equal(8 * 8, innerLogWriter.Count);
}
public void StoppingQueueLogWriterHaltsWriting()
{
var innerLogWriter = new TestLogWriter <MessageEntry>(SetupLog, false);
BackgroundMultiLogWriter backgroundMultiLogWriter;
IQueueEntryWriter <MessageEntry> queueEntryWriter;
SetupBackgroundLogWriter(innerLogWriter, out backgroundMultiLogWriter, out queueEntryWriter);
using (backgroundMultiLogWriter)
{
ExampleHelper.LogTestMessagesInParallel(queueEntryWriter, 8, 8, _testOutputHelper);
queueEntryWriter.Stop();
queueEntryWriter.Stop(); // Stopping twice shouldn't change things
// These messages aren't logged
ExampleHelper.LogTestMessagesInParallel(queueEntryWriter, 8, 8, _testOutputHelper);
queueEntryWriter.Start();
queueEntryWriter.Start(); // Starting twice shouldn't change things
ExampleHelper.LogTestMessagesInParallel(queueEntryWriter, 8, 8, _testOutputHelper);
}
Assert.False(backgroundMultiLogWriter.IsBackgroundThreadRunning);
Assert.Equal(2 * 8 * 8, innerLogWriter.Count);
}
public void CanRestartBackgroundMultiLogWriter()
{
var innerLogWriter = new TestLogWriter <MessageEntry>(SetupLog, false);
BackgroundMultiLogWriter backgroundMultiLogWriter;
IQueueEntryWriter <MessageEntry> queueEntryWriter;
SetupBackgroundLogWriter(innerLogWriter, out backgroundMultiLogWriter, out queueEntryWriter);
// Re-starting shouldn't hurt anything
Assert.True(backgroundMultiLogWriter.IsStarted);
backgroundMultiLogWriter.Start();
queueEntryWriter.Start();
// Log some, then Stop
ExampleHelper.LogTestMessagesInParallel(queueEntryWriter, 8, 8, _testOutputHelper);
backgroundMultiLogWriter.Stop(); // Blocks until the background thread exits
Assert.False(innerLogWriter.IsStarted);
Assert.False(backgroundMultiLogWriter.IsStarted);
Assert.Equal(8 * 8, innerLogWriter.Count);
// After a Stop(), logging does nothing
var msg = new MessageEntry("Logged while stopped - never logged.");
queueEntryWriter.Write(ref msg);
// After a Stop(), BackgroundMultiLogWriter and it's contained logwriters can be restarted
backgroundMultiLogWriter.Start();
// Log some, then Dispose
ExampleHelper.LogTestMessagesInParallel(queueEntryWriter, 8, 8, _testOutputHelper);
backgroundMultiLogWriter.Dispose(); // Blocks until the background thread exits
Assert.False(innerLogWriter.IsStarted);
Assert.False(backgroundMultiLogWriter.IsStarted);
Assert.Equal(2 * 8 * 8, innerLogWriter.Count);
// After a Dispose(), BackgroundMultiLogWriter can't be re-used
Assert.Throws <ObjectDisposedException>(() => backgroundMultiLogWriter.Start());
// Entries can still be written, though
queueEntryWriter.Write(ref msg);
}
public void BackgroundLoggingMakesSlowLoggerActFast()
{
// Hi-res timer
var stopwatch = new Stopwatch();
// Slow log writer - starting, stopping, disposing, writing an entry, all take at least 10ms each.
const int operationDelayMs = 30;
const int parallelThreads = 8;
const int messagesPerThread = 6;
var slowLogWriter = new SlowTestLogWriter <MessageEntry>(SetupLog, operationDelayMs, false);
BackgroundMultiLogWriter backgroundMultiLogWriter;
IQueueEntryWriter <MessageEntry> queueEntryWriter;
stopwatch.Start();
SetupBackgroundLogWriter(slowLogWriter, out backgroundMultiLogWriter, out queueEntryWriter);
stopwatch.Stop();
Assert.True((stopwatch.ElapsedMilliseconds <= operationDelayMs) || _inDebugger,
"Starting should be fast, slowLogWriter start delay should occur on background thread. Elapsed: " + stopwatch.ElapsedMilliseconds);
_testOutputHelper.WriteLine("Created + started BackgroundMultiLogWriter in {0}", stopwatch.Elapsed);
using (backgroundMultiLogWriter)
{
stopwatch.Restart();
ExampleHelper.LogTestMessagesInParallel(queueEntryWriter, messagesPerThread, parallelThreads, _testOutputHelper);
stopwatch.Stop();
Assert.True((stopwatch.ElapsedMilliseconds < operationDelayMs) || _inDebugger, "Log writing should be fast, until the queue is filled.");
stopwatch.Restart();
}
stopwatch.Stop();
_testOutputHelper.WriteLine("Stop + dispose took {0}", stopwatch.Elapsed);
// At this point, everything should have been logged
Assert.Equal(parallelThreads * messagesPerThread, slowLogWriter.Count);
Assert.True(stopwatch.ElapsedMilliseconds > messagesPerThread * parallelThreads * operationDelayMs,
"Dispose is slow, b/c we wait for all writes to complete on the background thread");
}
public void FinalizerCausesQueuedLogsToFlush()
{
var setupLog = new SetupLog();
// Slow log writer - starting, stopping, disposing, writing an entry, all take at least 10ms each.
const int opDelayMs = 5;
var slowLogWriter = new SlowTestLogWriter <MessageEntry>(setupLog, opDelayMs, false);
const int countLoggingThreads = 5;
const int countMessagesPerThread = 5;
const int expectedEntryCount = countLoggingThreads * countMessagesPerThread;
// Run the test code in a delegate so that local variable references can be GCed
Action logTestMessages = () =>
{
var logManager = new LogManager(new LogManagerConfig(), setupLog);
logManager.Config.UseLogWriter(slowLogWriter).BackgroundLogging = true;
var entryWriter = logManager.GetEntryWriter <MessageEntry>();
ExampleHelper.LogTestMessagesInParallel(entryWriter, countMessagesPerThread, countLoggingThreads, _testOutputHelper);
// Key point: The LogManager is never disposed, and it has a number of queued
// entries that haven't been written at this point.
};
logTestMessages();
Assert.True(slowLogWriter.Count < expectedEntryCount);
// Force a GC cyle, and wait for finalizers to complete.
GC.Collect();
GC.WaitForPendingFinalizers();
Assert.Equal(expectedEntryCount, slowLogWriter.Count);
// When the finalizer is called, an error is logged to the SetupLog.
Assert.True(setupLog.Any(traceEntry => (traceEntry.TraceLevel == TraceLevel.Error) && (traceEntry.Message.StartsWith("In finalizer "))));
}
public void DisposeBlocksUntilBackgroundLoggingCompletes()
{
// Slow log writer - starting, stopping, disposing, writing an entry, all take at least 20ms each.
const int operationDelayMs = 5;
const int parallelThreads = 8;
const int messagesPerThread = 6;
const int expectedMessageCount = parallelThreads * messagesPerThread;
var slowLogWriter = new SlowTestLogWriter <MessageEntry>(SetupLog, operationDelayMs, false);
BackgroundMultiLogWriter backgroundMultiLogWriter;
IQueueEntryWriter <MessageEntry> queueEntryWriter;
SetupBackgroundLogWriter(slowLogWriter, out backgroundMultiLogWriter, out queueEntryWriter);
using (backgroundMultiLogWriter)
{
ExampleHelper.LogTestMessagesInParallel(queueEntryWriter, messagesPerThread, parallelThreads, _testOutputHelper);
Assert.True(backgroundMultiLogWriter.IsBackgroundThreadRunning);
Assert.True(slowLogWriter.Count < expectedMessageCount);
// Dispose waits for all queued logs to complete, and for the background thread to exit
}
Assert.Equal(expectedMessageCount, slowLogWriter.Count);
Assert.False(backgroundMultiLogWriter.IsBackgroundThreadRunning);
}
