Add support for reporting application metrics via logging

[analogrelay]

Overview

We want to enable applications to emit arbitrary named metrics and have them captured by telemetry/logging systems (App Insights, Elasticsearch/ELK, etc.) as well as other metrics systems (Statsd, InfluxDB, etc.). An abstraction is desired in order to allow applications to emit metrics without being coupled to the destination of the metrics, particularly with features like App Insights auto-lightup where the app doesn't directly depend upon App Insights.

Proposal

We will add support for metrics reporting to ILogger. It will be done via a new companion interface IMetricsLogger, which loggers may optionally implement. Applications can emit metrics through this interface (see API below), and logger providers which support metrics can receive and process those metrics. Metrics are (name, value) tuples, where value is always floating point number. Metrics are expected to be viewed in aggregate, hence it doesn't make sense to use a generic data type like object for the metric, so metric values are always doubles. Supporting arbitrary types of metric values is a non-goal. Reporting metrics should be as efficient as possible, especially in the case where no logger provider is registered to listen for them, or they are filtered out.

Why add to ILogger?

Initially, I considered developing a new abstraction for Metrics. However, I encountered a few concerns:

1. We would need to develop a structure for naming/organizing metrics (likely using type/namespace names as a base)
2. We would need to develop a structure for filtering metrics (by categories, names, granularities, etc.)
3. Many telemetry systems provide support for both log and metric collection, and would have to provide a new system
4. Consumers have to pull in two different diagnostics reporters from DI (ILogger<T>, IMetricReporter<T>, etc.)
5. This would create Yet Another Diagnostics Abstraction (on top of EventSource, EventCounters, DiagnosticSource, Perf Counters, yada yada yada (see what I did there? ;P))

The fact that 1 and 2 above already exist in the Logging pipeline, and many metric sinks are also logging sinks, led to the idea of integrating metrics into Logging rather than creating a completely new abstraction.

The main reason why we would not want to add this to ILogger would be a risk

The API

IMetricLogger

Optional companion interface for ILogger implementations to indicate their support for metrics. The ILogger instances returned by ILoggerProvider are expected to implement this interface if and only if they wish to receive metrics.

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);
    }
}

IMetric

Interface that allows metric data to be reported. Metric values

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);
    }
}

LoggerMetricsExtensions

Provides an extension method on ILogger to enable consumers to emit metrics, even if the underlying logger provider doesn't support it (of course, the metrics will be ignored in that case).

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="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;
        }
    }
}

MetricValueExtensions

Extension methods for IMetric to support other common metric value types (as mentioned above, the underlying type is still double, so the value must be representable as a double).

Suggestion: We could have a .Time() API that returns an IDisposable which uses a Stopwatch to do the timing for you as well. That would be easy to add later though.

using System;

namespace Microsoft.Extensions.Logging
{
    public static class MetricValueExtensions
    {
        /// <summary>
        /// Record a new value for this metric.
        /// </summary>
        /// <remarks>
        /// This is a convenience method that will convert the <see cref="TimeSpan"/> to a <see cref="double"/> via
        /// the <see cref="TimeSpan.TotalMilliseconds"/> property.
        /// </remarks>
        /// <param name="metric">The metric to record the value on.</param>
        /// <param name="value">The value to record for this metric.</param>
        public static void RecordValue(this IMetric metric, TimeSpan value) => metric.RecordValue(value.TotalMilliseconds);
    }
}

Logger updates

The aggregate Logger class we return from LoggerFactory.CreateLogger would be updated to support IMetricsLogger, even if none of the ILoggers it aggregates support it. It would only send metrics to the loggers that are known to support the interface.

Define/Record pattern

In order to keep the performance cost as low as possible for recording the actual metric value, the API uses a Define/Record pattern. Consumers should expect to call DefineMetric("foo") once for a particular value of "foo" and store the result as globally as possible (in singleton types, etc.). It is DefineMetric that does the bulk of the work to set up the metric recording. After calling DefineMetric, the RecordValue call on the IMetric interface can choose how to store the value based on the providers needs. For example, in a provider that plans to send pre-aggregated metrics, the RecordValue could simply update rolling aggregate values and then drop the actual recording (thus having constant storage requirements for each metric). If a provider needs to report individual metrics, it can use dynamically-allocated buffers or ring buffers, depending upon the configuration and the needs of the provider. As an example of an IMetric implementation based on pre-aggregating data, see https://gist.github.com/anurse/03c6746204317bd3616c372b4df9dbba

Filtering Metrics

Metrics should be filterable, and they should participate in the existing Logger filtering pipeline. My current proposal is that Metrics are treated like LogLevel.Critical messages, in that if the category is enabled at all, the metrics are written. We could consider capturing a LogLevel in .DefineMetric and using that to provide different "levels" of metrics. Since the existing filters only let you filter by Provider, Category, and Level, it is very difficult to filter out specific metrics by name (as that would require a new Filter structure). This may make LogLevel support for metrics more important.

@pakrym and I talked and came up with a specific suggestion

Metrics can be filtered at the provider and category name, but there is no concept of a LogLevel for metrics. However, filters can disable all metrics for a particular provider/category combination. To do this, we'll add an AllowMetrics boolean to LoggerFilterRule which defaults to true. When writing a metric, we'll check the provider and category name against the filter options as well as checking this boolean.

Scopes and Property Bags

FEEDBACK REQUESTED

My initial thought is that Metrics exist outside of scopes, as they are generally aggregated and Scopes imply per-event data. Providers could, in theory, give their IMetric instances access to read active scope data, and attach them to metrics if they choose (for example, systems that report unaggregated metrics may want to). For similar reasons, property bags (i.e. Log Values/Structured Logging, etc.) don't really make sense for metrics in general as they are usually aggregated. Having said that, many providers do support arbitrary properties (InfluxDB, App Insights), so some level of support may be useful. We could easily add an optional parameter to .RecordValue to allow adding arbitrary properties to each metric, and providers could choose to disregard it if it doesn't make sense for that provider.

Impact on existing Providers

There is minimal impact on existing Providers. Because the interface provides an opt-in model for a provider to receive metrics, existing providers are unaffected. I'd imagine providers like Serilog would not participate in this system as they don't have an infrastructure for metrics (/cc @nblumhardt , I may be wrong!). Providers like App Insights may choose to either add metrics support to their existing providers or add new providers that only handle metrics (and ignore log messages) that are co-registered.

[analogrelay]

/cc @pakrym @davidfowl @glennc @muratg @Eilon

[analogrelay]

PR of initial implementation coming very soon!

[nblumhardt]

Thanks for the ping @anurse! Looks good from a Serilog perspective, AFAICT.

I've done some work with InfluxDB in this area; the single numeric value sounds fine, but the lack of support for key/value tags seems like it will limit the API's usefulness with Influx (not sure about other platforms).

In scenario terms -

• Recording transaction processing times, I want to slice the data by the particular transactions, by customer, by machine name, by database host IP... but still roll up aggregates over any of those dimensions (i.e. by considering them to belong to the same metric)
• Recording app startup time, I want to slice the data by app version, runtime version, OS and so-on... but still roll those up, and see the trend over time across multiple dimensions
• ... etc. (happy to provide more if it would help)

[analogrelay]

I want to slice the data by the particular transactions, by customer, by machine name, by database host IP... but still roll up aggregates over any of those dimensions

Yeah, I came to the same conclusion in my explorations with Influx. I think the pattern I'm leaning towards is allowing key-value pairs in RecordValue and allowing Providers to ignore them if they aren't relevant (ditto Scopes).

[analogrelay]

Properties/Scopes are a tricky one to solve well.

1. We want to be able to record a metric value without requiring an allocation. Thus, we want to use the same generic pattern we using for logging where we accept an arbitrary T (which could be a struct)
2. However, metrics are usually stashed away somewhere and then flushed to the back-end in a background process. This means structs would have to be boxed (unless you do something like a ring buffer, but even that is a stretch).
3. Scopes are even trickier because there could be a lot of data stored in the scopes, and much of it may be irrelevant to metrics. For example, the Request ID is not very relevant to metrics (use a log message if you want info on a single request), but Request Path is relevant (as multiple requests can share that attribute). It's impossible for a metric provider to know which fields matter for the metric. The more data associated with the metric, the more impact it has on the performance of the code being measured, which makes it a lot more difficult to use.

I'd lean towards supporting arbitrary properties, but discouraging providers from reading Scope data (we can't stop them from reading it ;)). It does mean that if I want to attach some arbitrary property to an EF metric (for example), I can't do it unless EF exposes a way to do it. Perhaps that's OK for now.

[alhardy]

Are metrics really a logging concern? If I were interested in tracking application metrics would it make sense to have to take a dependency on Microsoft.Extensions.Logging?

Have you guys looked at App Metrics for example?

This reminds me of when I noticed Health Checking functionality being added.

Once I noticed Health Checks being implemented by Microsoft I went to efforts to abstract that out of App Metrics, I don't see any progress on https://github.com/dotnet-architecture/HealthChecks anymore?

[muratg]

@glennc

[galvesribeiro]

@anurse a while ago, I added Telemetry APIs to Orleans (dotnet/orleans#992) which essentially add support to an abstraction that makes both trace/logging and metrics tracking mostly inspired on AI and NewRelic APIs.

Recently we removed the log/tracing from those APIs in favor of use Microsoft.Extensions.Logging abstractions so we would leverage most of the packages (like Serilog) that were already with its plugins for those abstractions.

Now, I'm going to revamp the telemetry APIs v2 and someone from the Orleans core team pointed me this issue out and would be good if we could use those metrics abstractions but I have some concerns about the way it is being implemented:

1. Why don't make IMetric<T> where T can be int, float, decimal, long? I think using double only is way restrictive.
2. Why not have it on Microsoft.Extensions.Metrics? I agree with @alhardy that metrics is not a Logging concern. If you think from the APM perspective, both metrics and trace/logging are telemetry-related concerns and they have correlation. So if you want to keep both together, I guess you would need a Microsoft.Extensions.Telemetry package otherwise, keep them separated would be better. I understood you want to leverage the categories infrastructure from MEL, but I guess it can be abstracted in another packages and be referenced by both MEL and MEM.
3. I'm not sure if Define/Record pattern is a good thing... Metrics carry much more metadata then that. They can or can not be aggregated, batched, auto-flushed or not, etc. There are much more configuration and it must be defined at the method creation time.
4. Property bags is definitively something that you will want to have support on all methods tracking metrics. Those bags carry context that makes sense for a given metric. i.e. if you are tracking an HttpRequest, you would include all the headers, browser and server details, etc. While tracking an exception, you would need context as well. Essentially an IDictionary<string, object> where object must be JSON serializable.

I would be interested in use it in Orleans but the way it is, it would limit us a lot.

[alhardy]

And here I am asked to remove my dependency on Microsoft.Extensions.Logging and Microsoft.Extensions.DependencyInjection AppMetrics/AppMetrics#186

I'm not sure why Microsoft is interested in including their own implementation to report metrics to OSS TSDBs like InfluxDB when they already have AppInsights? There doesn't seem to be much support from Microsoft in terms of OSS, wasn't this the idea of the dotnet foundation, rather than including everything possible in the dotnet framework?

App Metrics is my first attempt at an OSS project (other then contributing to other projects), rather than support from Microsoft, equivalent implementations are underway, Metrics and Health Checks. There are also other examples of this type of thing .NET developers have raised recently and in the past.

Microsoft I think has done amazing things all-round recently, very impressed, but the above makes me loose motivation in contributing to the dotnet community :(

[Eilon]

@alhardy we haven't decided to anything just yet! That's why we've logged this issue: to invite community discussion!

[Drawaes]

Here is my thoughts on this as someone who works in a very large corporate environment that has large logging as well as large telegraf/influxdb setups.

1. Absolutely the metrics need to be "baked" into the framework. So that all framework components will support/use them.
2. There is plenty of scope for "OSS", in the space of writing the adapters and aggregators
3. We have lost a bit with windows perf counters going xplat this would help fill that gap
4. Having to register your metric upfront leads to the problem you defined above around needing arbitrary extra key/value metadata added, instead.....

Make it so you can fire any metric and make the metric name a "namespace" effectively. So your metric maybe something like

http:response:200:/api/blabla|10

Or something like that. Then it's really up to the adapters to make it efficient and smart. In fact if you make the "key" just opaque bytes then you can deal with that however and cache those values.

Anyway just my 2p but this is a very important topic and one that I see as a weak point of c# aspnetcore apps in a big mixed Java/Go/C# ecosystem so I am happy this is being discussed!

[alhardy]

@Drawaes Yeah OK good points, in particular 1 and 3 👍

[cwe1ss]

As always, I'm adding my rant that you should sit together with Vance and the corefx team to not come up with yet another solution for very similar things.

E.g. metrics for operation-based things (like incoming / outgoing http requests) are already covered by Activity. People/metrics providers can just subscribe to activities and therefore re-use all the stuff that it offers (and has been requested above: timing, count, object context, tags).

Don't make us implement yet another abstraction in our frameworks/libraries - 283 lines of instrumentation code (as in the incoming ASP.NET Core request Diagnostics class) is enough. :)

See https://github.com/dotnet/corefx/issues/18114 for more context.

Give Activity some love and make sure it's easily usable and well documented.

People who need other kinds of metrics can always use e.g. AppMetrics which offers much more functionality anyway.

By introducing such a simple metrics abstraction in Microsoft.Extensions.*, you're just creating more Microsoft-internal competition and you're probably killing a great OSS project.

[davidfowl]

@cwe1ss how would you suggest we implement exposing the current connection count in SignalR and the number of websocket messages sent per second?