public void FinalizerCausesQueuedLogsToFlush()
{
// 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 expectedEntryCount = 25;
// Run the test code in a delegate so that local variable references can be GCed
Action logTestMessages = () =>
{
BackgroundMultiLogWriter backgroundMultiLogWriter;
IQueueEntryWriter <MessageEntry> queueEntryWriter;
SetupBackgroundLogWriter(slowLogWriter, out backgroundMultiLogWriter, out queueEntryWriter);
ExampleHelper.LogTestMessages(queueEntryWriter, expectedEntryCount);
// Key point: The BackgroundMultiLogWriter is never disposed, and it has a number of queued
// entries that haven't been written
};
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 ExceedingQueueSizeBlocksLogging()
{
// Slow log writer - starting, stopping, disposing, writing an entry, all take at least 10ms each.
const int opDelayMs = 50;
const int maxQueueLength = 10;
const int countBlockingWrites = 4;
var slowLogWriter = new SlowTestLogWriter <MessageEntry>(SetupLog, opDelayMs, false);
BackgroundMultiLogWriter backgroundMultiLogWriter;
IQueueEntryWriter <MessageEntry> queueEntryWriter;
SetupBackgroundLogWriter(slowLogWriter, out backgroundMultiLogWriter, out queueEntryWriter, maxQueueLength);
var stopwatch = Stopwatch.StartNew();
using (backgroundMultiLogWriter)
{
// First 10 messages log fast, then the queue is exactly full
ExampleHelper.LogTestMessages(queueEntryWriter, maxQueueLength);
stopwatch.Stop();
_testOutputHelper.WriteLine("First {0} writes took: {1}ms", maxQueueLength, stopwatch.ElapsedMilliseconds);
Assert.True(_inDebugger || (stopwatch.ElapsedMilliseconds <= opDelayMs), "Log writing should be fast, until the queue is filled.");
// Next writes block, since we've filled the queue
for (int i = 0; i < countBlockingWrites; ++i)
{
stopwatch.Restart();
ExampleHelper.LogTestMessages(queueEntryWriter, 1);
stopwatch.Stop();
long elapsedMilliseconds = stopwatch.ElapsedMilliseconds;
_testOutputHelper.WriteLine("Blocking write #{0}: {1}ms", i, elapsedMilliseconds);
Assert.True((elapsedMilliseconds >= (opDelayMs * 0.5)) || (i == 0) || _inDebugger,
"Expect blocking until 1 element is written - elapsed: " + elapsedMilliseconds);
// This assert is not passing on hqs01 - re-check another time.
// Timing-sensitive tests are always a bit delicate
//Assert.True((i == 0) || (elapsedMilliseconds < 2 * opDelayMs) || _inDebugger, "First write may be delayed; after that blocking should only occur for the duration of writing 1 entry. i=" + i + " Elapsed: " + elapsedMilliseconds);
}
stopwatch.Restart();
}
stopwatch.Stop();
_testOutputHelper.WriteLine("Stop + dispose took {0}", stopwatch.Elapsed);
// At this point, everything should have been logged
Assert.Equal(maxQueueLength + countBlockingWrites, slowLogWriter.Count);
Assert.True(stopwatch.ElapsedMilliseconds > maxQueueLength * opDelayMs, "Dispose writes all queued entries");
// maxQueueLength+2 is the number of sleeps to wait for - the queue is full, +2 is for Stop() + Dispose() sleeps
// 2.0 is just a tolerance for thread-related delays
Assert.True((stopwatch.ElapsedMilliseconds < (maxQueueLength + 2) * opDelayMs * 2.0) || _inDebugger, "Took longer than expected: " + stopwatch.ElapsedMilliseconds);
}
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);
}