diff --git a/Logging.sln b/Logging.sln index 4d02364a..e9e9ec18 100644 --- a/Logging.sln +++ b/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} diff --git a/samples/MetricsSample/MetricAggregates.cs b/samples/MetricsSample/MetricAggregates.cs new file mode 100644 index 00000000..aaa7aa2e --- /dev/null +++ b/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)); + } +} diff --git a/samples/MetricsSample/MetricsSample.csproj b/samples/MetricsSample/MetricsSample.csproj new file mode 100644 index 00000000..7f65596b --- /dev/null +++ b/samples/MetricsSample/MetricsSample.csproj @@ -0,0 +1,21 @@ + + + + Exe + netcoreapp2.0 + + + + latest + + + + + + + + + + + + diff --git a/samples/MetricsSample/Program.cs b/samples/MetricsSample/Program.cs new file mode 100644 index 00000000..c8d07c05 --- /dev/null +++ b/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(); + }); + + var serviceProvider = serviceCollection.BuildServiceProvider(); + var logger = serviceProvider.GetRequiredService>(); + + // 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)); + } + } + } +} diff --git a/samples/MetricsSample/SampleConsoleMetric.cs b/samples/MetricsSample/SampleConsoleMetric.cs new file mode 100644 index 00000000..b720f0a8 --- /dev/null +++ b/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(double value, T properties) where T : IEnumerable> => + RecordValue(value); + } +} diff --git a/samples/MetricsSample/SampleConsoleMetricsLogger.cs b/samples/MetricsSample/SampleConsoleMetricsLogger.cs new file mode 100644 index 00000000..7eaa35a1 --- /dev/null +++ b/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 state) + { + // REVIEW: Is this allowed? It works because Logger handles it, but... + return null; + } + + public bool IsEnabled(LogLevel logLevel) + { + return true; + } + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + } + } +} diff --git a/samples/MetricsSample/SampleConsoleMetricsLoggerProvider.cs b/samples/MetricsSample/SampleConsoleMetricsLoggerProvider.cs new file mode 100644 index 00000000..362e8a6e --- /dev/null +++ b/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, SampleConsoleMetric> _metrics = ImmutableDictionary.Create, 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)); + } + } +} diff --git a/samples/SampleApp/Program.cs b/samples/SampleApp/Program.cs index 7b692ca6..963b8c93 100644 --- a/samples/SampleApp/Program.cs +++ b/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); } } } diff --git a/src/Microsoft.Extensions.Logging.Abstractions/IMetric.cs b/src/Microsoft.Extensions.Logging.Abstractions/IMetric.cs new file mode 100644 index 00000000..13389250 --- /dev/null +++ b/src/Microsoft.Extensions.Logging.Abstractions/IMetric.cs @@ -0,0 +1,21 @@ +using System.Collections.Generic; + +namespace Microsoft.Extensions.Logging +{ + public interface IMetric + { + /// + /// Record a new value for this metric. + /// + /// The value to record for this metric + void RecordValue(double value); + + /// + /// Record a new value for this metric, including associated properties. + /// + /// The type of the object containing the properties + /// The value to record for this metric + /// Arbitrary properties to associate with the metric + void RecordValue(double value, T properties) where T: IEnumerable>; + } +} diff --git a/src/Microsoft.Extensions.Logging.Abstractions/IMetricLogger.cs b/src/Microsoft.Extensions.Logging.Abstractions/IMetricLogger.cs new file mode 100644 index 00000000..da6f16c9 --- /dev/null +++ b/src/Microsoft.Extensions.Logging.Abstractions/IMetricLogger.cs @@ -0,0 +1,12 @@ +namespace Microsoft.Extensions.Logging +{ + public interface IMetricLogger + { + /// + /// Define a new metric with the provided name and return an that can be used to report values for that metric. + /// + /// The name of the metric to define + /// An that can be used to report values for the metric + IMetric DefineMetric(string name); + } +} diff --git a/src/Microsoft.Extensions.Logging.Abstractions/LoggerMetricsExtensions.cs b/src/Microsoft.Extensions.Logging.Abstractions/LoggerMetricsExtensions.cs new file mode 100644 index 00000000..46aec906 --- /dev/null +++ b/src/Microsoft.Extensions.Logging.Abstractions/LoggerMetricsExtensions.cs @@ -0,0 +1,23 @@ +namespace Microsoft.Extensions.Logging +{ + public static class LoggerMetricsExtensions + { + /// + /// Define a new metric with the provided name and return an that can be used to report values for that metric. + /// + /// + /// If none of the registered logger providers support metrics, values recorded by this metric will be lost. + /// + /// The logger on which to define the metric + /// The name of the metric to define + /// An that can be used to report values for the metric + public static IMetric DefineMetric(this ILogger logger, string name) + { + if(logger is IMetricLogger metricLogger) + { + return metricLogger.DefineMetric(name); + } + return NullMetric.Instance; + } + } +} diff --git a/src/Microsoft.Extensions.Logging.Abstractions/LoggerOfT.cs b/src/Microsoft.Extensions.Logging.Abstractions/LoggerOfT.cs index b2ba187c..c6800e01 100644 --- a/src/Microsoft.Extensions.Logging.Abstractions/LoggerOfT.cs +++ b/src/Microsoft.Extensions.Logging.Abstractions/LoggerOfT.cs @@ -11,7 +11,7 @@ namespace Microsoft.Extensions.Logging /// provided . /// /// The type. - public class Logger : ILogger + public class Logger : ILogger, IMetricLogger { private readonly ILogger _logger; @@ -29,19 +29,9 @@ public Logger(ILoggerFactory factory) _logger = factory.CreateLogger(TypeNameHelper.GetTypeDisplayName(typeof(T))); } - IDisposable ILogger.BeginScope(TState state) - { - return _logger.BeginScope(state); - } - - bool ILogger.IsEnabled(LogLevel logLevel) - { - return _logger.IsEnabled(logLevel); - } - - void ILogger.Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) - { - _logger.Log(logLevel, eventId, state, exception, formatter); - } + IMetric IMetricLogger.DefineMetric(string name) => _logger.DefineMetric(name); + IDisposable ILogger.BeginScope(TState state) => _logger.BeginScope(state); + bool ILogger.IsEnabled(LogLevel logLevel) => _logger.IsEnabled(logLevel); + void ILogger.Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) => _logger.Log(logLevel, eventId, state, exception, formatter); } -} \ No newline at end of file +} diff --git a/src/Microsoft.Extensions.Logging.Abstractions/MetricValueExtensions.cs b/src/Microsoft.Extensions.Logging.Abstractions/MetricValueExtensions.cs new file mode 100644 index 00000000..3b120d96 --- /dev/null +++ b/src/Microsoft.Extensions.Logging.Abstractions/MetricValueExtensions.cs @@ -0,0 +1,18 @@ +using System; + +namespace Microsoft.Extensions.Logging +{ + public static class MetricValueExtensions + { + /// + /// Record a new value for this metric. + /// + /// + /// This is a convenience method that will convert the to a via + /// the property. + /// + /// The metric to record the value on. + /// The value to record for this metric. + public static void RecordValue(this IMetric metric, TimeSpan value) => metric.RecordValue(value.TotalMilliseconds); + } +} diff --git a/src/Microsoft.Extensions.Logging.Abstractions/NullMetric.cs b/src/Microsoft.Extensions.Logging.Abstractions/NullMetric.cs new file mode 100644 index 00000000..d70e148f --- /dev/null +++ b/src/Microsoft.Extensions.Logging.Abstractions/NullMetric.cs @@ -0,0 +1,22 @@ +using System.Collections.Generic; + +namespace Microsoft.Extensions.Logging +{ + public class NullMetric : IMetric + { + public static NullMetric Instance { get; } = new NullMetric(); + + private NullMetric() + { + + } + + public void RecordValue(double value) + { + } + + public void RecordValue(double value, T properties) where T : IEnumerable> + { + } + } +} diff --git a/src/Microsoft.Extensions.Logging.Console/ConsoleLogger.cs b/src/Microsoft.Extensions.Logging.Console/ConsoleLogger.cs index f0305d90..35a7b410 100644 --- a/src/Microsoft.Extensions.Logging.Console/ConsoleLogger.cs +++ b/src/Microsoft.Extensions.Logging.Console/ConsoleLogger.cs @@ -299,4 +299,5 @@ public void WriteLine(string message) } } } -} \ No newline at end of file +} + diff --git a/src/Microsoft.Extensions.Logging.Testing/ITestSink.cs b/src/Microsoft.Extensions.Logging.Testing/ITestSink.cs index 5c4d95f7..6380cf86 100644 --- a/src/Microsoft.Extensions.Logging.Testing/ITestSink.cs +++ b/src/Microsoft.Extensions.Logging.Testing/ITestSink.cs @@ -1,4 +1,4 @@ -using System; +using System; using System.Collections.Generic; namespace Microsoft.Extensions.Logging.Testing @@ -13,8 +13,12 @@ public interface ITestSink List Writes { get; set; } + List Metrics { get; set; } + void Write(WriteContext context); + void Write(MetricContext context); + void Begin(BeginScopeContext context); } } diff --git a/src/Microsoft.Extensions.Logging.Testing/MetricValue.cs b/src/Microsoft.Extensions.Logging.Testing/MetricValue.cs new file mode 100644 index 00000000..341781ed --- /dev/null +++ b/src/Microsoft.Extensions.Logging.Testing/MetricValue.cs @@ -0,0 +1,11 @@ +using System.Collections.Generic; + +namespace Microsoft.Extensions.Logging.Testing +{ + public class MetricContext + { + public string Name { get; set; } + public double Value { get; set; } + public IEnumerable> Properties { get; set; } + } +} diff --git a/src/Microsoft.Extensions.Logging.Testing/TestLogger.cs b/src/Microsoft.Extensions.Logging.Testing/TestLogger.cs index f7a73dfa..5d8fda33 100644 --- a/src/Microsoft.Extensions.Logging.Testing/TestLogger.cs +++ b/src/Microsoft.Extensions.Logging.Testing/TestLogger.cs @@ -5,7 +5,7 @@ namespace Microsoft.Extensions.Logging.Testing { - public class TestLogger : ILogger + public class TestLogger : ILogger, IMetricLogger { private object _scope; private readonly ITestSink _sink; @@ -63,6 +63,11 @@ public bool IsEnabled(LogLevel logLevel) return logLevel != LogLevel.None && _filter(logLevel); } + public IMetric DefineMetric(string name) + { + return new TestMetric(_sink, name); + } + private class TestDisposable : IDisposable { public static readonly TestDisposable Instance = new TestDisposable(); @@ -73,4 +78,4 @@ public void Dispose() } } } -} \ No newline at end of file +} diff --git a/src/Microsoft.Extensions.Logging.Testing/TestMetric.cs b/src/Microsoft.Extensions.Logging.Testing/TestMetric.cs new file mode 100644 index 00000000..da096eaf --- /dev/null +++ b/src/Microsoft.Extensions.Logging.Testing/TestMetric.cs @@ -0,0 +1,29 @@ +// 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.Collections.Generic; + +namespace Microsoft.Extensions.Logging.Testing +{ + public class TestMetric : IMetric + { + private ITestSink _sink; + private readonly string _name; + + public TestMetric(ITestSink sink, string name) + { + _sink = sink; + _name = name; + } + + public void RecordValue(double value) + { + _sink.Metrics.Add(new MetricContext() { Name = _name, Value = value }); + } + + public void RecordValue(double value, T properties) where T : IEnumerable> + { + _sink.Metrics.Add(new MetricContext() { Name = _name, Value = value, Properties = properties }); + } + } +} diff --git a/src/Microsoft.Extensions.Logging.Testing/TestSink.cs b/src/Microsoft.Extensions.Logging.Testing/TestSink.cs index 1b6f8de7..99809d58 100644 --- a/src/Microsoft.Extensions.Logging.Testing/TestSink.cs +++ b/src/Microsoft.Extensions.Logging.Testing/TestSink.cs @@ -17,6 +17,7 @@ public TestSink( Scopes = new List(); Writes = new List(); + Metrics = new List(); } public Func WriteEnabled { get; set; } @@ -27,6 +28,8 @@ public TestSink( public List Writes { get; set; } + public List Metrics { get; set; } + public void Write(WriteContext context) { if (WriteEnabled == null || WriteEnabled(context)) @@ -35,6 +38,11 @@ public void Write(WriteContext context) } } + public void Write(MetricContext context) + { + Metrics.Add(context); + } + public void Begin(BeginScopeContext context) { if (BeginEnabled == null || BeginEnabled(context)) @@ -53,4 +61,4 @@ public static bool EnableWithTypeName(BeginScopeContext context) return context.LoggerName.Equals(typeof(T).FullName); } } -} \ No newline at end of file +} diff --git a/src/Microsoft.Extensions.Logging.Testing/WriteContext.cs b/src/Microsoft.Extensions.Logging.Testing/WriteContext.cs index 4d5d4673..d187d41f 100644 --- a/src/Microsoft.Extensions.Logging.Testing/WriteContext.cs +++ b/src/Microsoft.Extensions.Logging.Testing/WriteContext.cs @@ -21,4 +21,5 @@ public class WriteContext public string LoggerName { get; set; } } -} \ No newline at end of file +} + diff --git a/src/Microsoft.Extensions.Logging/Logger.cs b/src/Microsoft.Extensions.Logging/Logger.cs index 4c593eea..aecc9b7c 100644 --- a/src/Microsoft.Extensions.Logging/Logger.cs +++ b/src/Microsoft.Extensions.Logging/Logger.cs @@ -7,8 +7,11 @@ namespace Microsoft.Extensions.Logging { - internal class Logger : ILogger + internal class Logger : ILogger, IMetricLogger { + private Dictionary _metrics = new Dictionary(); + private object _sync = new object(); + public LoggerInformation[] Loggers { get; set; } public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) @@ -136,6 +139,21 @@ public IDisposable BeginScope(TState state) return scope; } + public IMetric DefineMetric(string name) + { + if (!_metrics.TryGetValue(name, out var metric)) + { + lock (_sync) + { + if (!_metrics.TryGetValue(name, out metric)) + { + metric = new Metric(this, name); + _metrics[name] = metric; + } + } + } + return metric; + } private class Scope : IDisposable { @@ -197,5 +215,87 @@ public void Dispose() } } } + + private class Metric : IMetric + { + private readonly string _name; + + private Logger _logger; + private IMetric[] _metrics; + private object _sync = new object(); + + public Metric(Logger logger, string name) + { + _logger = logger; + _name = name; + } + + public void RecordValue(double value) + { + IMetric[] metrics; + lock (_sync) + { + if (_metrics == null || _metrics.Length != _logger.Loggers.Length) + { + UpdateMetrics(_logger.Loggers); + } + metrics = _metrics; + } + + for (var i = 0; i < metrics.Length; i += 1) + { + // REVIEW: LogLevel for metrics? + // REVIEW: Filtering by Metric Name? + if (_logger.Loggers[i].IsEnabled(LogLevel.Critical)) + { + metrics[i].RecordValue(value); + } + } + } + + public void RecordValue(double value, T properties) where T : IEnumerable> + { + IMetric[] metrics; + lock (_sync) + { + if (_metrics == null || _metrics.Length != _logger.Loggers.Length) + { + UpdateMetrics(_logger.Loggers); + } + metrics = _metrics; + } + + for (var i = 0; i < metrics.Length; i += 1) + { + if (_logger.Loggers[i].MetricsEnabled) + { + metrics[i].RecordValue(value, properties); + } + } + } + + private void UpdateMetrics(LoggerInformation[] loggers) + { + lock (_sync) + { + if (_metrics == null) + { + _metrics = new IMetric[loggers.Length]; + } + else if (_metrics.Length != loggers.Length) + { + Array.Resize(ref _metrics, loggers.Length); + } + + for (var i = 0; i < loggers.Length; i += 1) + { + if (_metrics[i] == null) + { + _metrics[i] = loggers[i].Logger.DefineMetric(_name); + } + } + } + } + } } -} \ No newline at end of file +} diff --git a/src/Microsoft.Extensions.Logging/LoggerFactory.cs b/src/Microsoft.Extensions.Logging/LoggerFactory.cs index a4622b17..0b4dad6c 100644 --- a/src/Microsoft.Extensions.Logging/LoggerFactory.cs +++ b/src/Microsoft.Extensions.Logging/LoggerFactory.cs @@ -1,4 +1,4 @@ -// 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; @@ -131,11 +131,13 @@ private void ApplyRules(LoggerInformation[] loggers, string categoryName, int st loggerInformation.ProviderType, categoryName, out var minLevel, - out var filter); + out var filter, + out var metricsEnabled); loggerInformation.Category = categoryName; loggerInformation.MinLevel = minLevel; loggerInformation.Filter = filter; + loggerInformation.MetricsEnabled = metricsEnabled; } } @@ -176,4 +178,4 @@ private struct ProviderRegistration public bool ShouldDispose; } } -} \ No newline at end of file +} diff --git a/src/Microsoft.Extensions.Logging/LoggerFilterRule.cs b/src/Microsoft.Extensions.Logging/LoggerFilterRule.cs index 197ea02c..7bd7cb8f 100644 --- a/src/Microsoft.Extensions.Logging/LoggerFilterRule.cs +++ b/src/Microsoft.Extensions.Logging/LoggerFilterRule.cs @@ -11,6 +11,11 @@ namespace Microsoft.Extensions.Logging public class LoggerFilterRule { public LoggerFilterRule(string providerName, string categoryName, LogLevel? logLevel, Func filter) + : this(providerName, categoryName, logLevel, filter, metricsEnabled: true) + { + } + + public LoggerFilterRule(string providerName, string categoryName, LogLevel? logLevel, Func filter, bool metricsEnabled) { ProviderName = providerName; CategoryName = categoryName; @@ -38,9 +43,14 @@ public LoggerFilterRule(string providerName, string categoryName, LogLevel? logL /// public Func Filter { get; } + /// + /// Gets a boolean indicating if metrics are enabled for this logger. + /// + public bool MetricsEnabled { get; } + public override string ToString() { - return $"{nameof(ProviderName)}: '{ProviderName}', {nameof(CategoryName)}: '{CategoryName}', {nameof(LogLevel)}: '{LogLevel}', {nameof(Filter)}: '{Filter}'"; + return $"{nameof(ProviderName)}: '{ProviderName}', {nameof(CategoryName)}: '{CategoryName}', {nameof(LogLevel)}: '{LogLevel}', {nameof(Filter)}: '{Filter}', {nameof(MetricsEnabled)}: {MetricsEnabled}"; } } -} \ No newline at end of file +} diff --git a/src/Microsoft.Extensions.Logging/LoggerInformation.cs b/src/Microsoft.Extensions.Logging/LoggerInformation.cs index 8c6e2f86..8d94ab6f 100644 --- a/src/Microsoft.Extensions.Logging/LoggerInformation.cs +++ b/src/Microsoft.Extensions.Logging/LoggerInformation.cs @@ -1,4 +1,4 @@ -// 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; @@ -17,6 +17,8 @@ internal struct LoggerInformation public Func Filter { get; set; } + public bool MetricsEnabled { get; set; } + public bool IsEnabled(LogLevel level) { if (MinLevel != null && level < MinLevel) @@ -32,4 +34,4 @@ public bool IsEnabled(LogLevel level) return true; } } -} \ No newline at end of file +} diff --git a/src/Microsoft.Extensions.Logging/LoggerRuleSelector.cs b/src/Microsoft.Extensions.Logging/LoggerRuleSelector.cs index 2a66f782..b412c442 100644 --- a/src/Microsoft.Extensions.Logging/LoggerRuleSelector.cs +++ b/src/Microsoft.Extensions.Logging/LoggerRuleSelector.cs @@ -11,10 +11,11 @@ internal class LoggerRuleSelector private const string AliasAttibuteTypeFullName = "Microsoft.Extensions.Logging.ProviderAliasAttribute"; private const string AliasAttibuteAliasProperty = "Alias"; - public void Select(LoggerFilterOptions options, Type providerType, string category, out LogLevel? minLevel, out Func filter) + public void Select(LoggerFilterOptions options, Type providerType, string category, out LogLevel? minLevel, out Func filter, out bool metricsEnabled) { filter = null; minLevel = options.MinLevel; + metricsEnabled = true; // Filter rule selection: // 1. Select rules for current logger type, if there is none, select ones without logger type specified @@ -39,6 +40,7 @@ public void Select(LoggerFilterOptions options, Type providerType, string catego { filter = current.Filter; minLevel = current.LogLevel; + metricsEnabled = current.MetricsEnabled; } } @@ -107,4 +109,4 @@ private static bool IsBetter(LoggerFilterRule rule, LoggerFilterRule current, st return true; } } -} \ No newline at end of file +} diff --git a/src/Microsoft.Extensions.Logging/Microsoft.Extensions.Logging.csproj b/src/Microsoft.Extensions.Logging/Microsoft.Extensions.Logging.csproj index 96b113fc..7b1ffb18 100644 --- a/src/Microsoft.Extensions.Logging/Microsoft.Extensions.Logging.csproj +++ b/src/Microsoft.Extensions.Logging/Microsoft.Extensions.Logging.csproj @@ -13,6 +13,7 @@ + diff --git a/test/Microsoft.Extensions.Logging.Test/ConsoleLoggerTest.cs b/test/Microsoft.Extensions.Logging.Test/ConsoleLoggerTest.cs index 0faa1350..990b4e51 100644 --- a/test/Microsoft.Extensions.Logging.Test/ConsoleLoggerTest.cs +++ b/test/Microsoft.Extensions.Logging.Test/ConsoleLoggerTest.cs @@ -903,7 +903,7 @@ public static void IsEnabledReturnsCorrectValue() public void ConsoleLoggerOptions_IncludeScopes_IsAppliedToLoggers() { // Arrange - var monitor = new TestOptionsMonitor(new ConsoleLoggerOptions() { IncludeScopes = true }); + var monitor = TestOptionsMonitor.Create(new ConsoleLoggerOptions() { IncludeScopes = true }); var loggerProvider = new ConsoleLoggerProvider(monitor); var logger = (ConsoleLogger)loggerProvider.CreateLogger("Name"); @@ -968,7 +968,7 @@ public bool TryGetSwitch(string name, out LogLevel level) return true; } - throw new Exception("Failed to parse LogLevel"); + throw new Exception($"Failed to parse LogLevel: {Switches[name]}"); } } @@ -984,31 +984,4 @@ public override void EnqueueMessage(LogMessageEntry message) } } } - - public class TestOptionsMonitor : IOptionsMonitor - { - private ConsoleLoggerOptions _options; - private event Action _onChange; - - public TestOptionsMonitor(ConsoleLoggerOptions options) - { - _options = options; - } - - public ConsoleLoggerOptions Get(string name) => _options; - - public IDisposable OnChange(Action listener) - { - _onChange += listener; - return null; - } - - public ConsoleLoggerOptions CurrentValue => _options; - - public void Set(ConsoleLoggerOptions options) - { - _options = options; - _onChange?.Invoke(options, ""); - } - } } diff --git a/test/Microsoft.Extensions.Logging.Test/LoggerFilterTest.cs b/test/Microsoft.Extensions.Logging.Test/LoggerFilterTest.cs index 0c50b220..cc26580a 100644 --- a/test/Microsoft.Extensions.Logging.Test/LoggerFilterTest.cs +++ b/test/Microsoft.Extensions.Logging.Test/LoggerFilterTest.cs @@ -1,4 +1,4 @@ -// 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; diff --git a/test/Microsoft.Extensions.Logging.Test/LoggerMessageTest.cs b/test/Microsoft.Extensions.Logging.Test/LoggerMessageTest.cs index 1738c1ce..b0b89295 100644 --- a/test/Microsoft.Extensions.Logging.Test/LoggerMessageTest.cs +++ b/test/Microsoft.Extensions.Logging.Test/LoggerMessageTest.cs @@ -1,4 +1,4 @@ -// 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; diff --git a/test/Microsoft.Extensions.Logging.Test/LoggerMetricsTest.cs b/test/Microsoft.Extensions.Logging.Test/LoggerMetricsTest.cs new file mode 100644 index 00000000..6e503faf --- /dev/null +++ b/test/Microsoft.Extensions.Logging.Test/LoggerMetricsTest.cs @@ -0,0 +1,171 @@ +using System.Collections.Generic; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging.Testing; +using Microsoft.Extensions.Options; +using Xunit; + +namespace Microsoft.Extensions.Logging.Test +{ + public class LoggerMetricsTest + { + [Fact] + public void DefineMetric_ReturnsSameInstanceForSameName() + { + var testSink = new TestSink(); + var loggerFactory = TestLoggerBuilder.Create(builder => builder + .AddProvider(new TestLoggerProvider(testSink, isEnabled: true))); + + var logger = loggerFactory.CreateLogger("test"); + + Assert.Same(logger.DefineMetric("foo"), logger.DefineMetric("foo")); + } + + [Fact] + public void RecordValue_WritesValueToRegisteredMetricsProviders() + { + var testSink1 = new TestSink(); + var testSink2 = new TestSink(); + var loggerFactory = TestLoggerBuilder.Create(builder => builder + .AddProvider(new TestLoggerProvider(testSink1, isEnabled: true)) + .AddProvider(new TestLoggerProvider(testSink2, isEnabled: true))); + + var logger = loggerFactory.CreateLogger("test"); + var metric = logger.DefineMetric("test"); + metric.RecordValue(42.0); + + Assert.Collection(testSink1.Metrics, + item => + { + Assert.Equal("test", item.Name); + Assert.Equal(42.0, item.Value); + }); + + Assert.Collection(testSink2.Metrics, + item => + { + Assert.Equal("test", item.Name); + Assert.Equal(42.0, item.Value); + }); + } + + [Fact] + public void RecordValue_DoesntWriteMetricToProviderWithoutMetricsSupport() + { + var testSink1 = new TestSink(); + var testSink2 = new TestSink(); + var loggerFactory = TestLoggerBuilder.Create(builder => builder + .AddProvider(new TestLoggerProviderWithoutMetrics(testSink1, isEnabled: true)) + .AddProvider(new TestLoggerProvider(testSink2, isEnabled: true))); + + var logger = loggerFactory.CreateLogger("test"); + var metric = logger.DefineMetric("test"); + metric.RecordValue(42.0); + + Assert.Empty(testSink1.Metrics); + + Assert.Collection(testSink2.Metrics, + item => + { + Assert.Equal("test", item.Name); + Assert.Equal(42.0, item.Value); + }); + } + + [Fact] + public void AddProvider_UpdatesMetricOutputs() + { + var testSink1 = new TestSink(); + var testSink2 = new TestSink(); + var loggerFactory = TestLoggerBuilder.Create(builder => builder + .AddProvider(new TestLoggerProvider(testSink1, isEnabled: true))); + + var logger = loggerFactory.CreateLogger("test"); + var metric = logger.DefineMetric("test"); + + // This will only go to testSink1 + metric.RecordValue(42.0); + + // Now add a provider + loggerFactory.AddProvider(new TestLoggerProvider(testSink2, isEnabled: true)); + + // This should go to both sinks + metric.RecordValue(24.0); + + Assert.Collection(testSink1.Metrics, + item => + { + Assert.Equal("test", item.Name); + Assert.Equal(42.0, item.Value); + }, + item => + { + Assert.Equal("test", item.Name); + Assert.Equal(24.0, item.Value); + }); + + Assert.Collection(testSink2.Metrics, + item => + { + Assert.Equal("test", item.Name); + Assert.Equal(24.0, item.Value); + }); + } + + [Fact] + public void ConfigurationChanges_UpdateMetricOutputs() + { + var filterOptions = new LoggerFilterOptions(); + + // Filter out TestLoggerProvider2 + filterOptions.Rules.Add(new LoggerFilterRule( + providerName: typeof(TestLoggerProvider2).FullName, + categoryName: null, + logLevel: LogLevel.None, + filter: null)); + + var optionsMonitor = TestOptionsMonitor.Create(filterOptions); + + var testSink1 = new TestSink(); + var testSink2 = new TestSink(); + var loggerFactory = TestLoggerBuilder.Create(builder => + { + builder.Services.AddSingleton>(optionsMonitor); + builder + .AddProvider(new TestLoggerProvider(testSink1, isEnabled: true)) + .AddProvider(new TestLoggerProvider2(testSink2)); + }); + + var logger = loggerFactory.CreateLogger("test"); + var metric = logger.DefineMetric("test"); + + // This will only go to testSink1 because of the filter + metric.RecordValue(42.0); + + // Now remove the rule and update the options + filterOptions.Rules.Clear(); + optionsMonitor.NotifyChanged(); + + // This should go to both sinks + metric.RecordValue(24.0); + + Assert.Collection(testSink1.Metrics, + item => + { + Assert.Equal("test", item.Name); + Assert.Equal(42.0, item.Value); + }, + item => + { + Assert.Equal("test", item.Name); + Assert.Equal(24.0, item.Value); + }); + + Assert.Collection(testSink2.Metrics, + item => + { + Assert.Equal("test", item.Name); + Assert.Equal(24.0, item.Value); + }); + } + } +} diff --git a/test/Microsoft.Extensions.Logging.Test/TestLoggerProvider.cs b/test/Microsoft.Extensions.Logging.Test/TestLoggerProvider.cs index 3dac9375..9e68bfb8 100644 --- a/test/Microsoft.Extensions.Logging.Test/TestLoggerProvider.cs +++ b/test/Microsoft.Extensions.Logging.Test/TestLoggerProvider.cs @@ -11,7 +11,7 @@ namespace Microsoft.Extensions.Logging.Test #pragma warning restore CS0436 // Type conflicts with imported type public class TestLoggerProvider : ILoggerProvider { - private readonly Func _filter; + protected readonly Func _filter; public TestLoggerProvider(TestSink testSink, bool isEnabled) : this(testSink, _ => isEnabled) @@ -28,7 +28,7 @@ public TestLoggerProvider(TestSink testSink, Func filter) public bool DisposeCalled { get; private set; } - public ILogger CreateLogger(string categoryName) + public virtual ILogger CreateLogger(string categoryName) { return new TestLogger(categoryName, Sink, _filter); } @@ -45,4 +45,23 @@ public TestLoggerProvider2(TestSink testSink) : base(testSink, true) { } } + + // Need a logger that does not implement IMetricsLogger to test that functionality. + public class TestLoggerProviderWithoutMetrics : TestLoggerProvider + { + public TestLoggerProviderWithoutMetrics(TestSink testSink, bool isEnabled) : + base(testSink, isEnabled) + { + } + + public TestLoggerProviderWithoutMetrics(TestSink testSink, Func filter) + : base(testSink, filter) + { + } + + public override ILogger CreateLogger(string categoryName) + { + return new TestLoggerWithoutMetrics(categoryName, Sink, _filter); + } + } } \ No newline at end of file diff --git a/test/Microsoft.Extensions.Logging.Test/TestLoggerWithoutMetrics.cs b/test/Microsoft.Extensions.Logging.Test/TestLoggerWithoutMetrics.cs new file mode 100644 index 00000000..122cb781 --- /dev/null +++ b/test/Microsoft.Extensions.Logging.Test/TestLoggerWithoutMetrics.cs @@ -0,0 +1,40 @@ +// 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 Microsoft.Extensions.Logging.Testing; + +namespace Microsoft.Extensions.Logging.Test +{ + // Just wraps a TestLogger but does so in a type that doesn't implement IMetricsLogger + // Didn't put this in Microsoft.Extensions.Logging.Testing because it's not really necessary for general testing of logging, + // just for testing the logging infrastructure itself. + public class TestLoggerWithoutMetrics : ILogger + { + private readonly TestLogger _innerLogger; + + public TestLoggerWithoutMetrics(string name, ITestSink sink, bool enabled) + { + _innerLogger = new TestLogger(name, sink, enabled); + } + + public TestLoggerWithoutMetrics(string name, ITestSink sink, Func filter) + { + _innerLogger = new TestLogger(name, sink, filter); + } + public IDisposable BeginScope(TState state) + { + return ((ILogger)_innerLogger).BeginScope(state); + } + + public bool IsEnabled(LogLevel logLevel) + { + return _innerLogger.IsEnabled(logLevel); + } + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + ((ILogger)_innerLogger).Log(logLevel, eventId, state, exception, formatter); + } + } +} diff --git a/test/Microsoft.Extensions.Logging.Test/TestOptionsMonitor.cs b/test/Microsoft.Extensions.Logging.Test/TestOptionsMonitor.cs new file mode 100644 index 00000000..d4c57287 --- /dev/null +++ b/test/Microsoft.Extensions.Logging.Test/TestOptionsMonitor.cs @@ -0,0 +1,46 @@ +// 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 Microsoft.Extensions.Options; + +namespace Microsoft.Extensions.Logging.Test +{ + public static class TestOptionsMonitor + { + public static TestOptionsMonitor Create(T options) => new TestOptionsMonitor(options); + } + + public class TestOptionsMonitor : IOptionsMonitor + { + private T _options; + private event Action _onChange; + + public TestOptionsMonitor(T options) + { + _options = options; + } + + public T Get(string name) => _options; + + public IDisposable OnChange(Action listener) + { + _onChange += listener; + return null; + } + + public T CurrentValue => _options; + + public void Set(T options) + { + _options = options; + NotifyChanged(); + } + + // Useful when the change is just done by changing the options object in-place rather than specifying a new one. + public void NotifyChanged() + { + _onChange?.Invoke(_options, ""); + } + } +}