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");
        }
Пример #4
0
        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);
        }