Initial pass at Metrics support in ILogger

Logging.sln

@@ -1,6 +1,6 @@
 Microsoft Visual Studio Solution File, Format Version 12.00
 # Visual Studio 15
-VisualStudioVersion = 15.0.26814.1
+VisualStudioVersion = 15.0.26913.0
 MinimumVisualStudioVersion = 10.0.40219.1
 Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Microsoft.Extensions.Logging", "src\Microsoft.Extensions.Logging\Microsoft.Extensions.Logging.csproj", "{19D1B6C5-8A62-4387-8816-C54874D1DF5F}"
 EndProject
@@ -60,6 +60,8 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Microsoft.Extensions.Loggin
 EndProject
 Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Microsoft.Extensions.Logging.Analyzer.Test", "test\Microsoft.Extensions.Logging.Analyzer.Test\Microsoft.Extensions.Logging.Analyzer.Test.csproj", "{C0391E46-FD04-4D52-BE40-1F21CE83E037}"
 EndProject
+Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "MetricsSample", "samples\MetricsSample\MetricsSample.csproj", "{1D30FF1D-33B6-45B0-9C5D-4D9044A4E49C}"
+EndProject
 Global
 	GlobalSection(SolutionConfigurationPlatforms) = preSolution
 		Debug|Any CPU = Debug|Any CPU
@@ -134,6 +136,22 @@ Global
 		{C0391E46-FD04-4D52-BE40-1F21CE83E037}.Debug|Any CPU.Build.0 = Debug|Any CPU
 		{C0391E46-FD04-4D52-BE40-1F21CE83E037}.Release|Any CPU.ActiveCfg = Release|Any CPU
 		{C0391E46-FD04-4D52-BE40-1F21CE83E037}.Release|Any CPU.Build.0 = Release|Any CPU
+		{6D921637-507E-4CDC-8C5F-C3D6B62D118C}.Release|Mixed Platforms.ActiveCfg = Release|Any CPU
+		{6D921637-507E-4CDC-8C5F-C3D6B62D118C}.Release|Mixed Platforms.Build.0 = Release|Any CPU
+		{6D921637-507E-4CDC-8C5F-C3D6B62D118C}.Release|x86.ActiveCfg = Release|Any CPU
+		{6D921637-507E-4CDC-8C5F-C3D6B62D118C}.Release|x86.Build.0 = Release|Any CPU
+		{1D30FF1D-33B6-45B0-9C5D-4D9044A4E49C}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
+		{1D30FF1D-33B6-45B0-9C5D-4D9044A4E49C}.Debug|Any CPU.Build.0 = Debug|Any CPU
+		{1D30FF1D-33B6-45B0-9C5D-4D9044A4E49C}.Debug|Mixed Platforms.ActiveCfg = Debug|Any CPU
+		{1D30FF1D-33B6-45B0-9C5D-4D9044A4E49C}.Debug|Mixed Platforms.Build.0 = Debug|Any CPU
+		{1D30FF1D-33B6-45B0-9C5D-4D9044A4E49C}.Debug|x86.ActiveCfg = Debug|Any CPU
+		{1D30FF1D-33B6-45B0-9C5D-4D9044A4E49C}.Debug|x86.Build.0 = Debug|Any CPU
+		{1D30FF1D-33B6-45B0-9C5D-4D9044A4E49C}.Release|Any CPU.ActiveCfg = Release|Any CPU
+		{1D30FF1D-33B6-45B0-9C5D-4D9044A4E49C}.Release|Any CPU.Build.0 = Release|Any CPU
+		{1D30FF1D-33B6-45B0-9C5D-4D9044A4E49C}.Release|Mixed Platforms.ActiveCfg = Release|Any CPU
+		{1D30FF1D-33B6-45B0-9C5D-4D9044A4E49C}.Release|Mixed Platforms.Build.0 = Release|Any CPU
+		{1D30FF1D-33B6-45B0-9C5D-4D9044A4E49C}.Release|x86.ActiveCfg = Release|Any CPU
+		{1D30FF1D-33B6-45B0-9C5D-4D9044A4E49C}.Release|x86.Build.0 = Release|Any CPU
 	EndGlobalSection
 	GlobalSection(SolutionProperties) = preSolution
 		HideSolutionNode = FALSE
@@ -156,6 +174,7 @@ Global
 		{6D921637-507E-4CDC-8C5F-C3D6B62D118C} = {699DB330-0095-4266-B7B0-3EAB3710CA49}
 		{99DF369F-40A4-4088-8308-1C361B59DF4E} = {699DB330-0095-4266-B7B0-3EAB3710CA49}
 		{C0391E46-FD04-4D52-BE40-1F21CE83E037} = {09920C51-6220-4D8D-94DC-E70C13446187}
+		{1D30FF1D-33B6-45B0-9C5D-4D9044A4E49C} = {8C1F5D80-88EA-4961-84DC-7AC6E13951F4}
 	EndGlobalSection
 	GlobalSection(ExtensibilityGlobals) = postSolution
 		SolutionGuid = {BA58E3CA-3A01-46A7-B57F-FD7A188EDC79}

samples/MetricsSample/MetricAggregates.cs

@@ -0,0 +1,27 @@
+using System;
+
+namespace MetricsSample
+{
+    public struct MetricAggregates
+    {
+        public int Count { get; }
+        public double Sum { get; }
+        public double SumOfSquares { get; }
+        public double? Max { get; }
+        public double? Min { get; }
+
+        public MetricAggregates(int count, double sum, double sumOfSquares, double? max, double? min)
+        {
+            Count = count;
+            Sum = sum;
+            SumOfSquares = sumOfSquares;
+            Max = max;
+            Min = min;
+        }
+
+        public double GetMean() => Sum / Count;
+
+        // Estimated std-dev via online sum-of-squares method.
+        public double GetStdDev() => Math.Sqrt((SumOfSquares - ((Sum * Sum) / Count)) / (Count - 1));
+    }
+}

samples/MetricsSample/MetricsSample.csproj

@@ -0,0 +1,21 @@
+<Project Sdk="Microsoft.NET.Sdk">
+
+  <PropertyGroup>
+    <OutputType>Exe</OutputType>
+    <TargetFramework>netcoreapp2.0</TargetFramework>
+  </PropertyGroup>
+
+  <PropertyGroup Condition="'$(Configuration)|$(Platform)'=='Debug|AnyCPU'">
+    <LangVersion>latest</LangVersion>
+  </PropertyGroup>
+
+  <ItemGroup>
+    <ProjectReference Include="..\..\src\Microsoft.Extensions.Logging.Console\Microsoft.Extensions.Logging.Console.csproj" />
+    <ProjectReference Include="..\..\src\Microsoft.Extensions.Logging\Microsoft.Extensions.Logging.csproj" />
+  </ItemGroup>
+
+  <ItemGroup>
+    <PackageReference Include="Microsoft.Extensions.DependencyInjection" />
+  </ItemGroup>
+
+</Project>

samples/MetricsSample/Program.cs

@@ -0,0 +1,50 @@
+using System;
+using System.Threading;
+using System.Threading.Tasks;
+using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.Logging;
+
+namespace MetricsSample
+{
+    class Program
+    {
+        private static readonly int ThreadCount = 100;
+
+        static void Main(string[] args)
+        {
+            // A Web App based program would configure logging via the WebHostBuilder.
+            // Create a logger factory with filters that can be applied across all logger providers.
+            var serviceCollection = new ServiceCollection()
+                .AddLogging(builder =>
+                {
+                    builder.AddConsole();
+                    builder.Services.AddSingleton<ILoggerProvider, SampleConsoleMetricsLoggerProvider>();
+                });
+
+            var serviceProvider = serviceCollection.BuildServiceProvider();
+            var logger = serviceProvider.GetRequiredService<ILogger<Program>>();
+
+            // Spin up a whole bunch of "threads"
+            var cts = new CancellationTokenSource();
+            var tasks = new Task[ThreadCount];
+            var metric = logger.DefineMetric("RandomValue");
+            for (var i = 0; i < ThreadCount; i += 1)
+            {
+                tasks[i] = Task.Factory.StartNew(() => RunWorker(i, metric, cts.Token), TaskCreationOptions.LongRunning);
+            }
+
+            cts.CancelAfter(TimeSpan.FromSeconds(10));
+
+            Task.WaitAll(tasks);
+        }
+
+        private static void RunWorker(int i, IMetric metric, CancellationToken cancellationToken)
+        {
+            var rando = new Random();
+            while (!cancellationToken.IsCancellationRequested)
+            {
+                metric.RecordValue(rando.Next(1, 100));
+            }
+        }
+    }
+}

samples/MetricsSample/SampleConsoleMetric.cs

@@ -0,0 +1,61 @@
+using System.Collections.Generic;
+using Microsoft.Extensions.Logging;
+
+namespace MetricsSample
+{
+    internal class SampleConsoleMetric : IMetric
+    {
+        private readonly SampleConsoleMetricsLoggerProvider _loggerProvider;
+
+        private object _lock = new object();
+
+        private int _count;
+        private double _sum;
+        private double _sumOfSquares;
+        private double? _max;
+        private double? _min;
+
+        public string CategoryName { get; }
+        public string Name { get; }
+
+        public SampleConsoleMetric(string categoryName, string name, SampleConsoleMetricsLoggerProvider loggerProvider)
+        {
+            _count = 0;
+            _sum = 0;
+            _sumOfSquares = 0;
+            CategoryName = categoryName;
+            Name = name;
+            _loggerProvider = loggerProvider;
+        }
+
+        public void RecordValue(double value)
+        {
+            lock (_lock)
+            {
+                if (_max == null || _max.Value < value)
+                {
+                    _max = value;
+                }
+                if (_min == null || _min.Value > value)
+                {
+                    _min = value;
+                }
+                _count += 1;
+                _sum += value;
+                _sumOfSquares += (value * value);
+            }
+        }
+
+        public MetricAggregates GetAggregates()
+        {
+            lock (_lock)
+            {
+                return new MetricAggregates(_count, _sum, _sumOfSquares, _max, _min);
+            }
+        }
+
+        // We don't care about the properties
+        public void RecordValue<T>(double value, T properties) where T : IEnumerable<KeyValuePair<string, object>> =>
+            RecordValue(value);
+    }
+}

samples/MetricsSample/SampleConsoleMetricsLogger.cs

@@ -0,0 +1,42 @@
+using System;
+using System.Collections.Generic;
+using System.Collections.Immutable;
+using System.Threading;
+using Microsoft.Extensions.Logging;
+
+namespace MetricsSample
+{
+    internal class SampleConsoleMetricsLogger : ILogger, IMetricLogger
+    {
+        private string _categoryName;
+        private readonly SampleConsoleMetricsLoggerProvider _loggerProvider;
+
+        public SampleConsoleMetricsLogger(string categoryName, SampleConsoleMetricsLoggerProvider loggerProvider)
+        {
+            _categoryName = categoryName;
+            _loggerProvider = loggerProvider;
+        }
+
+        public IMetric DefineMetric(string name)
+        {
+            // Use the logger-provider's root list of metrics.
+            return _loggerProvider.DefineMetric(_categoryName, name);
+        }
+
+        // No-ops for non-metrics.
+        public IDisposable BeginScope<TState>(TState state)
+        {
+            // REVIEW: Is this allowed? It works because Logger handles it, but...
+            return null;
+        }
+
+        public bool IsEnabled(LogLevel logLevel)
+        {
+            return true;
+        }
+
+        public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
+        {
+        }
+    }
+}

samples/MetricsSample/SampleConsoleMetricsLoggerProvider.cs

@@ -0,0 +1,52 @@
+using System;
+using System.Collections.Immutable;
+using System.Threading;
+using Microsoft.Extensions.Logging;
+
+namespace MetricsSample
+{
+    public class SampleConsoleMetricsLoggerProvider : ILoggerProvider
+    {
+        private ImmutableDictionary<ValueTuple<string, string>, SampleConsoleMetric> _metrics = ImmutableDictionary.Create<ValueTuple<string, string>, SampleConsoleMetric>();
+        private readonly Timer _worker;
+
+        public SampleConsoleMetricsLoggerProvider()
+        {
+            // Create a timer to flush metrics
+            _worker = new Timer(self => ((SampleConsoleMetricsLoggerProvider)self).Worker(), this, TimeSpan.FromSeconds(1), TimeSpan.FromSeconds(1));
+        }
+
+        private void Worker()
+        {
+            foreach(var metric in _metrics.Values)
+            {
+                ReportMetric(metric);
+            }
+        }
+
+        private void ReportMetric(SampleConsoleMetric metric)
+        {
+            var aggregates = metric.GetAggregates();
+            if (aggregates.Count > 0)
+            {
+                Console.WriteLine($"Metric({metric.Name}): N={aggregates.Count}, Σ={aggregates.Sum}, σ={aggregates.GetStdDev()}, max={aggregates.Max}, min={aggregates.Min}");
+            }
+        }
+
+        public ILogger CreateLogger(string categoryName)
+        {
+            return new SampleConsoleMetricsLogger(categoryName, this);
+        }
+
+        public void Dispose()
+        {
+            _worker.Dispose();
+        }
+
+        internal IMetric DefineMetric(string categoryName, string name)
+        {
+            var key = (categoryName, name);
+            return ImmutableInterlocked.GetOrAdd(ref _metrics, key, k => new SampleConsoleMetric(k.Item1, k.Item2, this));
+        }
+    }
+}

samples/SampleApp/Program.cs

@@ -1,7 +1,8 @@
-// Copyright (c) .NET Foundation. All rights reserved.
+// Copyright (c) .NET Foundation. All rights reserved.
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
+using System.Diagnostics;
 using System.IO;
 using Microsoft.Extensions.Configuration;
 using Microsoft.Extensions.DependencyInjection;
@@ -55,6 +56,8 @@ public static void Main(string[] args)
 
         public void Execute(string[] args)
         {
+            var durationMetric = _logger.DefineMetric("Duration");
+            var stopwatch = Stopwatch.StartNew();
             _logger.LogInformation("Starting");
 
             var startTime = DateTimeOffset.Now;
@@ -99,6 +102,9 @@ public void Execute(string[] args)
             _logger.ProgramStopping(endTime);
 
             _logger.LogInformation("Stopping");
+
+            stopwatch.Stop();
+            durationMetric.RecordValue(stopwatch.Elapsed);
         }
     }
 }

src/Microsoft.Extensions.Logging.Abstractions/IMetric.cs

@@ -0,0 +1,21 @@
+using System.Collections.Generic;
+
+namespace Microsoft.Extensions.Logging
+{
+    public interface IMetric
+    {
+        /// <summary>
+        /// Record a new value for this metric.
+        /// </summary>
+        /// <param name="value">The value to record for this metric</param>
+        void RecordValue(double value);
+
+        /// <summary>
+        /// Record a new value for this metric, including associated properties.
+        /// </summary>
+        /// <typeparam name="T">The type of the object containing the properties</typeparam>
+        /// <param name="value">The value to record for this metric</param>
+        /// <param name="properties">Arbitrary properties to associate with the metric</param>
+        void RecordValue<T>(double value, T properties) where T: IEnumerable<KeyValuePair<string, object>>;
+    }
+}

src/Microsoft.Extensions.Logging.Abstractions/IMetricLogger.cs

@@ -0,0 +1,12 @@
+namespace Microsoft.Extensions.Logging
+{
+    public interface IMetricLogger
+    {
+        /// <summary>
+        /// Define a new metric with the provided name and return an <see cref="IMetric"/> that can be used to report values for that metric.
+        /// </summary>
+        /// <param name="name">The name of the metric to define</param>
+        /// <returns>An <see cref="IMetric"/> that can be used to report values for the metric</returns>
+        IMetric DefineMetric(string name);
+    }
+}

src/Microsoft.Extensions.Logging.Abstractions/LoggerMetricsExtensions.cs

@@ -0,0 +1,23 @@
+namespace Microsoft.Extensions.Logging
+{
+    public static class LoggerMetricsExtensions
+    {
+        /// <summary>
+        /// Define a new metric with the provided name and return an <see cref="IMetric"/> that can be used to report values for that metric.
+        /// </summary>
+        /// <remarks>
+        /// If none of the registered logger providers support metrics, values recorded by this metric will be lost.
+        /// </remarks>
+        /// <param name="logger">The logger on which to define the metric</param>
+        /// <param name="name">The name of the metric to define</param>
+        /// <returns>An <see cref="IMetric"/> that can be used to report values for the metric</returns>
+        public static IMetric DefineMetric(this ILogger logger, string name)
+        {
+            if(logger is IMetricLogger metricLogger)
+            {
+                return metricLogger.DefineMetric(name);
+            }
+            return NullMetric.Instance;
+        }
+    }
+}