Put ConsoleLogger writes on a background thread #551

BrennanConroy · 2017-02-09T18:42:29Z

Built on top of #536 from @benaadams

benaadams · 2017-02-09T18:59:37Z

src/Microsoft.Extensions.Logging.Console/Internal/ConsoleLoggerProcessor.cs

+            }
+        }
+
+        public bool HasQueuedMessages => _messageQueue.Count > 0;


BlockingCollection doesn't expose .IsEmpty from the underlying ConcurrentQueue; but testing against .Count > 0 is a lot more expensive.

Wonder if you should use the explicit BlockingCollection(IProducerConsumerCollection<T> collection, int boundedCapacity) ctor and pass in as the ctor you are calling does; but keep a reference to a ConcurrentQueue for the fast IsEmpty test?

Or not expose the new HasQueuedMessages property on ConsoleLogger...

We could make it internal, its only used for testing right now

Or if it's really important, instead of using BlockingCollection, just use a ConcurrentQueue and a SemaphoreSlim.

Would make it internal till someone wants it public; else its exposing a impl detail that someone will take a dependency on...

davidfowl · 2017-02-10T06:18:00Z

src/Microsoft.Extensions.Logging.Console/Internal/ConsoleLoggerProcessor.cs

+            consoleLogger.ProcessLogQueue();
+        }
+
+        private void RegisterForExit()


I'd remove all of this and just make this disposable. Then call that from the console logger's dispose. Logger providers are disposed "at the right time" when wired up correctly.

Unfortunately loggers aren't IDisposable

Move this to the ConsoleLoggerProvider (those are disposable)

davidfowl · 2017-02-10T06:19:01Z

src/Microsoft.Extensions.Logging.Console/Internal/ConsoleLoggerProcessor.cs

+
+        public void EnqueueMessage(LogMessageEntry message)
+        {
+            _messageQueue.Add(message);


Does this dispatch?

Just adds to the internal data structure and the GetConsumingEnumerable below is waiting for messages to be added on a separate thread

davidfowl · 2017-02-10T06:58:25Z

src/Microsoft.Extensions.Logging.Console/ConsoleLogger.cs

@@ -86,6 +75,8 @@ public IConsole Console

        public string Name { get; }

+        public bool HasQueuedMessages => _queueProcessor.HasQueuedMessages;


Remove this, I don't think we need to expose it.

davidfowl · 2017-02-10T06:59:48Z

src/Microsoft.Extensions.Logging.Console/Internal/ConsoleLoggerProcessor.cs

+{
+    public class ConsoleLoggerProcessor
+    {
+        private const int _maxQueuedMessages = 1024;


What happens when you hit the limit? Does it block the producer?

davidfowl · 2017-02-10T07:06:34Z

We need some throughput tests before and after.

BrennanConroy · 2017-02-10T17:21:45Z

I'll do some perf testing today

glennc · 2017-02-13T19:56:15Z

Test results? :)

BrennanConroy · 2017-02-14T00:02:12Z

Metric	Before	After
Average (RPS)	4001.162	5007.562
Max (RPS)	4618.2	6120.87
Standard deviation	824.096	824.499

CPU was around 100% the whole time

davidfowl · 2017-02-14T16:31:36Z

src/Microsoft.Extensions.Logging.Console/ConsoleLogger.cs

        private static readonly string _loglevelPadding = ": ";
        private static readonly string _messagePadding;
        private static readonly string _newLineWithMessagePadding;

        // ConsoleColor does not have a value to specify the 'Default' color
        private readonly ConsoleColor? DefaultConsoleColor = null;

-        private IConsole _console;
+        private readonly ConsoleLoggerProcessor _queueProcessor = new ConsoleLoggerProcessor();


This spins up a thread per logger category, we need to move this to the provider so there's a single thread and remeasure.

davidfowl · 2017-02-15T04:35:39Z

src/Microsoft.Extensions.Logging.Console/Internal/ConsoleLoggerProcessor.cs

        {
-            // TODO: Do after _outputTask.Wait(...) in case there are items blocked on getting added?
            _messageQueue.CompleteAdding();


Why is Dispose throwing?

You mean the ones we catch and ignore?

Ah yes we just swallow 😄 .Good

davidfowl · 2017-02-15T17:18:21Z

src/Microsoft.Extensions.Logging.Console/ConsoleLogger.cs

        private Func<string, LogLevel, bool> _filter;
+        private IConsole _console;


Why not just pass the QueueProcessor as a ctor argument and set the IConsole on the QueueProcessor instead of on the message?

Public constructor, internal type. I can do the second one

davidfowl · 2017-02-16T01:26:51Z

src/Microsoft.Extensions.Logging.Console/ConsoleLogger.cs

        private static readonly string _loglevelPadding = ": ";
        private static readonly string _messagePadding;
        private static readonly string _newLineWithMessagePadding;

        // ConsoleColor does not have a value to specify the 'Default' color
        private readonly ConsoleColor? DefaultConsoleColor = null;

-        private IConsole _console;
+        private ConsoleLoggerProcessor _queueProcessor;


davidfowl · 2017-02-17T06:50:25Z

src/Microsoft.Extensions.Logging.Console/Internal/ConsoleLoggerProcessor.cs

+{
+    public class ConsoleLoggerProcessor : IDisposable
+    {
+        private const int _maxQueuedMessages = 1024;


File an issue to make this configurable.

davidfowl

LGTM

davidfowl · 2017-02-17T06:54:28Z

src/Microsoft.Extensions.Logging.Console/Internal/ConsoleLoggerProcessor.cs

+        public ConsoleLoggerProcessor()
+        {
+            // Start Console message queue processor
+            _outputTask = Task.Factory.StartNew(


I think we should file an issue to avoid using a dedicated thread. It's probably fine for the most part but it can be done in a way where we don't have a thread spun up all the time. I don't know how much of a problem it is in practice though.

dnfclas added the cla-already-signed label Feb 9, 2017

BrennanConroy mentioned this pull request Feb 9, 2017

Move Console.Write out of critial path #536

Closed

benaadams reviewed Feb 9, 2017

View reviewed changes

davidfowl reviewed Feb 10, 2017

View reviewed changes

davidfowl reviewed Feb 14, 2017

View reviewed changes

davidfowl reviewed Feb 15, 2017

View reviewed changes

davidfowl reviewed Feb 16, 2017

View reviewed changes

BrennanConroy force-pushed the brecon/background branch from 0073dbd to ebc1c6e Compare February 16, 2017 17:53

davidfowl reviewed Feb 17, 2017

View reviewed changes

davidfowl approved these changes Feb 17, 2017

View reviewed changes

davidfowl reviewed Feb 17, 2017

View reviewed changes

benaadams and others added 2 commits February 17, 2017 08:49

Move Console.Write out of critial path

c321853

Use BlockingCollection<T>

db73396

BrennanConroy force-pushed the brecon/background branch from 7ab9fd7 to db73396 Compare February 17, 2017 16:56

BrennanConroy merged commit db73396 into dev Feb 17, 2017

BrennanConroy deleted the brecon/background branch February 17, 2017 17:13

BrennanConroy mentioned this pull request Feb 17, 2017

Background console logging #519

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Put ConsoleLogger writes on a background thread #551

Put ConsoleLogger writes on a background thread #551

BrennanConroy commented Feb 9, 2017

benaadams Feb 9, 2017 •

edited

Loading

BrennanConroy Feb 9, 2017

stephentoub Feb 9, 2017

benaadams Feb 9, 2017

davidfowl Feb 10, 2017

BrennanConroy Feb 10, 2017

davidfowl Feb 14, 2017

davidfowl Feb 10, 2017

BrennanConroy Feb 10, 2017

davidfowl Feb 10, 2017

davidfowl Feb 10, 2017

BrennanConroy Feb 10, 2017

davidfowl Feb 10, 2017

davidfowl commented Feb 10, 2017

BrennanConroy commented Feb 10, 2017

glennc commented Feb 13, 2017

BrennanConroy commented Feb 14, 2017

davidfowl Feb 14, 2017 •

edited

Loading

davidfowl Feb 15, 2017

BrennanConroy Feb 15, 2017

davidfowl Feb 15, 2017

davidfowl Feb 15, 2017

BrennanConroy Feb 15, 2017

davidfowl Feb 16, 2017

davidfowl Feb 17, 2017

davidfowl left a comment

davidfowl Feb 17, 2017

		@@ -86,6 +75,8 @@ public IConsole Console

		public string Name { get; }

		public bool HasQueuedMessages => _queueProcessor.HasQueuedMessages;

		private Func<string, LogLevel, bool> _filter;
		private IConsole _console;

Put ConsoleLogger writes on a background thread #551

Put ConsoleLogger writes on a background thread #551

Conversation

BrennanConroy commented Feb 9, 2017

benaadams Feb 9, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

davidfowl commented Feb 10, 2017

BrennanConroy commented Feb 10, 2017

glennc commented Feb 13, 2017

BrennanConroy commented Feb 14, 2017

davidfowl Feb 14, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

davidfowl left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

benaadams Feb 9, 2017 •

edited

Loading

davidfowl Feb 14, 2017 •

edited

Loading