diff --git a/src/Roastery/Api/OrdersController.cs b/src/Roastery/Api/OrdersController.cs index ce0efecf..35c34eb5 100644 --- a/src/Roastery/Api/OrdersController.cs +++ b/src/Roastery/Api/OrdersController.cs @@ -2,6 +2,7 @@ using System.Net; using System.Threading.Tasks; using Roastery.Data; +using Roastery.Metrics; using Roastery.Model; using Roastery.Web; using Serilog; @@ -15,8 +16,8 @@ class OrdersController : Controller { readonly Database _database; - public OrdersController(ILogger logger, Database database) - : base(logger) + public OrdersController(ILogger logger, RoasteryMetrics metrics, Database database) + : base(logger, metrics) { _database = database; } @@ -41,7 +42,10 @@ public async Task Create(HttpRequest request) } await _database.InsertAsync(order); + + Metrics.RecordOrderCreated(); Log.Information("Created new order {OrderId} for customer {CustomerName}", order.Id, order.CustomerName); + return Json(order, HttpStatusCode.Created); } @@ -65,7 +69,11 @@ public async Task Update(HttpRequest request) if (order.Status == OrderStatus.PendingShipment) Log.Information("Order placed and ready for shipment"); else if (order.Status == OrderStatus.Shipped) - Log.Information("Order shipped to {CustomerName} at {ShippingAddress}", order.CustomerName, order.ShippingAddress); + { + Metrics.RecordOrderShipped(); + Log.Information("Order shipped to {CustomerName} at {ShippingAddress}", order.CustomerName, + order.ShippingAddress); + } else Log.Information("Order updated"); diff --git a/src/Roastery/Api/ProductsController.cs b/src/Roastery/Api/ProductsController.cs index 22710017..dacd5e2b 100644 --- a/src/Roastery/Api/ProductsController.cs +++ b/src/Roastery/Api/ProductsController.cs @@ -1,5 +1,6 @@ using System.Threading.Tasks; using Roastery.Data; +using Roastery.Metrics; using Roastery.Model; using Roastery.Web; using Serilog; @@ -12,8 +13,8 @@ class ProductsController : Controller { readonly Database _database; - public ProductsController(ILogger logger, Database database) - : base(logger) + public ProductsController(ILogger logger, RoasteryMetrics metrics, Database database) + : base(logger, metrics) { _database = database; } diff --git a/src/Roastery/Metrics/ExponentialHistogram.cs b/src/Roastery/Metrics/ExponentialHistogram.cs new file mode 100644 index 00000000..8e3db4bf --- /dev/null +++ b/src/Roastery/Metrics/ExponentialHistogram.cs @@ -0,0 +1,65 @@ +using System; +using System.Collections.Generic; + +namespace Roastery.Metrics; + +public class ExponentialHistogram +{ + public ExponentialHistogram(int initialScale = 20, int targetBuckets = 160) + { + _scale = initialScale; + _targetBuckets = targetBuckets; + _buckets = new Dictionary(); + } + + readonly int _targetBuckets; + + int _scale; + Dictionary _buckets; + + double _min; + double _max; + ulong _total; + + public void Record(double rawValue) + { + _min = Math.Min(_min, rawValue); + _max = Math.Max(_max, rawValue); + _total += 1; + + var midpoint = Midpoint(_scale, rawValue); + _buckets.TryAdd(midpoint, 0); + _buckets[midpoint] += 1; + + if (_buckets.Count <= _targetBuckets) return; + + // Rescale + var newScale = _scale - 1; + var newBuckets = new Dictionary(); + + foreach (var (oldMidpoint, count) in _buckets) + { + var newMidpoint = Midpoint(_scale, oldMidpoint); + newBuckets.TryAdd(newMidpoint, 0); + newBuckets[newMidpoint] += count; + } + + _buckets = newBuckets; + _scale = newScale; + } + + static double Midpoint(int scale, double rawValue) + { + var gamma = Math.Pow(2d, Math.Pow(2d, -scale)); + var index = Math.Abs(Math.Log(rawValue, gamma)); + + return (Math.Pow(gamma, index - 1) + Math.Pow(gamma, index)) / 2; + } + + public IReadOnlyDictionary Buckets => _buckets; + public int Scale => _scale; + + public double Min => _min; + public double Max => _max; + public ulong Total => _total; +} diff --git a/src/Roastery/Metrics/PropertyNameMapping.cs b/src/Roastery/Metrics/PropertyNameMapping.cs new file mode 100644 index 00000000..bcd3fdfd --- /dev/null +++ b/src/Roastery/Metrics/PropertyNameMapping.cs @@ -0,0 +1,3 @@ +namespace Roastery.Metrics; + +public record struct PropertyNameMapping(string MetricDefinitions, string MetricSamples); diff --git a/src/Roastery/Metrics/RoasteryMetrics.cs b/src/Roastery/Metrics/RoasteryMetrics.cs new file mode 100644 index 00000000..9beb225c --- /dev/null +++ b/src/Roastery/Metrics/RoasteryMetrics.cs @@ -0,0 +1,174 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; +using Serilog; +using Serilog.Events; +using Serilog.Parsing; + +namespace Roastery.Metrics; + +public class RoasteryMetrics +{ + public class Sample + { + /* + Adding new metrics: + + 1. Add a new key type, `TKey` for the metric's attributes using structural equality. + 2. Add a `Dictionary` property for the metric where `TMetric` is its collection type. + 3. Add a method to `RoasterMetrics` to add a sample to the metric for a given key. + 4. Add support in `ToLogEvents` for the new metric. + */ + + // `HttpRequestDuration`: histogram + public record struct HttpRequestDurationKey(string Path, int StatusCode); + public readonly Dictionary HttpRequestDuration = new(); + + // `OrdersCreated`: counter + public ulong OrdersCreated; + + // `OrdersShipped`: counter + public ulong OrdersShipped; + + static readonly MessageTemplate Template = new MessageTemplateParser().Parse("Metrics sampled"); + + public IEnumerable ToLogEvents(ILogger logger, PropertyNameMapping propertyNameMapping, DateTimeOffset timestamp) + { + foreach (var (key, metric) in HttpRequestDuration) + { + yield return ToLogEvent( + logger, + propertyNameMapping, + timestamp, + new Dictionary + { + { "HttpRequestDuration", new { kind = "Exponential", unit = "ms", description = "The time taken to fully process a request" } } + }, + new + { + HttpRequestDuration = new { + buckets = metric.Buckets + .Select(bucket => new { midpoint = bucket.Key, count = bucket.Value }).ToArray(), + scale = metric.Scale, + min = metric.Min, + max = metric.Max, + count = metric.Total + }, + key.Path, + key.StatusCode + } + ); + } + + yield return ToLogEvent( + logger, + propertyNameMapping, + timestamp, + new Dictionary + { + { "OrdersCreated", new { kind = "Counter", unit = "orders", description = "The total number of orders created in the system" } }, + { "OrdersShipped", new { kind = "Counter", unit = "orders", description = "The total number of orders shipped in the system" } } + }, + new + { + OrdersCreated, + OrdersShipped + } + ); + } + + static LogEvent ToLogEvent(ILogger logger, PropertyNameMapping propertyNameMapping, DateTimeOffset timestamp, Dictionary definitions, object samples) + { + logger.BindProperty(propertyNameMapping.MetricDefinitions, definitions, true, out var definitionsProperty); + logger.BindProperty(propertyNameMapping.MetricSamples, samples, true, out var sampleProperty); + + return new LogEvent(timestamp, LogEventLevel.Information, null, Template, + [definitionsProperty!, sampleProperty!]); + } + } + + // Access to the current sample is synchronized through a lock + // This is a simple way to implement deltas for arbitrary types + readonly Lock _lock = new(); + Sample _current = new(); + + public void RecordHttpRequestDuration(Sample.HttpRequestDurationKey key, double rawValue) + { + lock (_lock) + { + if (!_current.HttpRequestDuration.TryGetValue(key, out var metric)) + { + metric = new ExponentialHistogram(); + _current.HttpRequestDuration.Add(key, metric); + } + + metric.Record(rawValue); + } + } + + public void RecordOrderCreated() + { + lock (_lock) + { + _current.OrdersCreated += 1; + } + } + + public void RecordOrderShipped() + { + lock (_lock) + { + _current.OrdersShipped += 1; + } + } + + public (DateTimeOffset, Sample) Take() + { + var timestamp = DateTimeOffset.UtcNow; + + var current = new Sample(); + + lock (_lock) + { + (current, _current) = (_current, current); + } + + return (timestamp, current); + } + + public static Task PeriodicSample( + RoasteryMetrics metrics, + TimeSpan samplingInterval, + Func sample, + CancellationToken cancellationToken) + { + return Task.Run(async () => + { + var waitFor = samplingInterval; + while (!cancellationToken.IsCancellationRequested) + { + await Task.Delay(waitFor, cancellationToken); + + var stopwatch = Stopwatch.StartNew(); + + try + { + var (timestamp, current) = metrics.Take(); + await sample(timestamp, current, cancellationToken); + } + catch + { + // Ignored + } + + // Account for the time taken to produce the sample when computing + // the next interval to wait for + var elapsed = stopwatch.Elapsed; + waitFor = elapsed < samplingInterval ? samplingInterval - stopwatch.Elapsed : samplingInterval; + } + }, cancellationToken); + } +} diff --git a/src/Roastery/Program.cs b/src/Roastery/Program.cs index 00f587f5..acef4206 100644 --- a/src/Roastery/Program.cs +++ b/src/Roastery/Program.cs @@ -1,4 +1,5 @@ -using System.Collections.Generic; +using System; +using System.Collections.Generic; using System.Linq; using System.Threading; using System.Threading.Tasks; @@ -6,6 +7,7 @@ using Roastery.Api; using Roastery.Data; using Roastery.Fake; +using Roastery.Metrics; using Roastery.Util; using Roastery.Web; using Serilog; @@ -15,22 +17,35 @@ namespace Roastery; // Named this way to make stack traces a little more believable :-) public static class Program { - public static async Task Main(ILogger logger, CancellationToken cancellationToken = default) + public static async Task Main(ILogger logger, PropertyNameMapping propertyNameMapping, CancellationToken cancellationToken = default) { + var metrics = new RoasteryMetrics(); + var webApplicationLogger = logger.ForContext("Application", "Roastery Web Frontend"); + // Sample metrics + var periodicSample = RoasteryMetrics.PeriodicSample(metrics, TimeSpan.FromSeconds(5), (timestamp, sample, ct) => + { + foreach (var evt in sample.ToLogEvents(webApplicationLogger, propertyNameMapping, timestamp)) + { + webApplicationLogger.Write(evt); + } + + return Task.CompletedTask; + }, cancellationToken); + var database = new Database(webApplicationLogger, "roastery"); DatabaseMigrator.Populate(database); var client = new HttpClient( "https://roastery.datalust.co", new NetworkLatencyMiddleware( - new RequestLoggingMiddleware(webApplicationLogger, + new RequestLoggingMiddleware(webApplicationLogger, metrics, new SchedulingLatencyMiddleware( new FaultInjectionMiddleware(webApplicationLogger, new Router([ - new OrdersController(logger, database), - new ProductsController(logger, database) + new OrdersController(logger, metrics, database), + new ProductsController(logger, metrics, database) ], webApplicationLogger)))))); var agents = new List(); @@ -46,5 +61,6 @@ public static async Task Main(ILogger logger, CancellationToken cancellationToke agents.Add(new ArchivingBatch(client, batchApplicationLogger)); await Task.WhenAll(agents.Select(a => Agent.Run(a, cancellationToken))); + await periodicSample; } } \ No newline at end of file diff --git a/src/Roastery/Web/Controller.cs b/src/Roastery/Web/Controller.cs index 73aa8c77..a16cd83b 100644 --- a/src/Roastery/Web/Controller.cs +++ b/src/Roastery/Web/Controller.cs @@ -1,4 +1,5 @@ using System.Net; +using Roastery.Metrics; using Serilog; namespace Roastery.Web; @@ -6,10 +7,12 @@ namespace Roastery.Web; abstract class Controller { protected ILogger Log { get; } - - protected Controller(ILogger logger) + protected RoasteryMetrics Metrics { get; } + + protected Controller(ILogger logger, RoasteryMetrics metrics) { Log = logger.ForContext(GetType()); + Metrics = metrics; } protected static HttpResponse Json(object? body, HttpStatusCode statusCode = HttpStatusCode.OK) diff --git a/src/Roastery/Web/RequestLoggingMiddleware.cs b/src/Roastery/Web/RequestLoggingMiddleware.cs index f0cdb784..3219152a 100644 --- a/src/Roastery/Web/RequestLoggingMiddleware.cs +++ b/src/Roastery/Web/RequestLoggingMiddleware.cs @@ -1,6 +1,9 @@ using System; +using System.Diagnostics; +using System.Diagnostics.Metrics; using System.Net; using System.Threading.Tasks; +using Roastery.Metrics; using Serilog; using Serilog.Context; using Serilog.Events; @@ -12,23 +15,29 @@ class RequestLoggingMiddleware : HttpServer { readonly HttpServer _next; readonly ILogger _logger; - - public RequestLoggingMiddleware(ILogger logger, HttpServer next) + readonly RoasteryMetrics _metrics; + + public RequestLoggingMiddleware(ILogger logger, RoasteryMetrics metrics, HttpServer next) { _next = next; _logger = logger.ForContext(); + _metrics = metrics; } public override async Task InvokeAsync(HttpRequest request) { using var _ = LogContext.PushProperty("RequestId", request.RequestId); + var requestTiming = Stopwatch.StartNew(); using var activity = _logger.StartActivity("HTTP {RequestMethod} {RequestPath}", request.Method, request.Path); try { var response = await _next.InvokeAsync(request); + LogCompletion(activity, null, response.StatusCode); + _metrics.RecordHttpRequestDuration(new RoasteryMetrics.Sample.HttpRequestDurationKey(request.Path, (int)response.StatusCode), requestTiming.ElapsedMilliseconds); + return response; } catch (Exception ex1) when (LogCompletion(activity, ex1, HttpStatusCode.InternalServerError)) @@ -38,7 +47,10 @@ public override async Task InvokeAsync(HttpRequest request) } catch { - return new HttpResponse(HttpStatusCode.InternalServerError, "An error occurred."); + var statusCode = HttpStatusCode.InternalServerError; + + _metrics.RecordHttpRequestDuration(new RoasteryMetrics.Sample.HttpRequestDurationKey(request.Path, (int)statusCode), requestTiming.ElapsedMilliseconds); + return new HttpResponse(statusCode, "An error occurred."); } } diff --git a/src/SeqCli/Apps/Hosting/AppContainer.cs b/src/SeqCli/Apps/Hosting/AppContainer.cs index 72184492..90e05667 100644 --- a/src/SeqCli/Apps/Hosting/AppContainer.cs +++ b/src/SeqCli/Apps/Hosting/AppContainer.cs @@ -20,7 +20,7 @@ using Newtonsoft.Json.Linq; using Seq.Apps; using Seq.Apps.LogEvents; -using SeqCli.Levels; +using SeqCli.Mapping; using Serilog; using Serilog.Events; using Serilog.Formatting.Compact.Reader; diff --git a/src/SeqCli/Cli/Commands/ApiKey/CreateCommand.cs b/src/SeqCli/Cli/Commands/ApiKey/CreateCommand.cs index 437fe98a..5ebbfb08 100644 --- a/src/SeqCli/Cli/Commands/ApiKey/CreateCommand.cs +++ b/src/SeqCli/Cli/Commands/ApiKey/CreateCommand.cs @@ -22,7 +22,7 @@ using SeqCli.Api; using SeqCli.Cli.Features; using SeqCli.Config; -using SeqCli.Levels; +using SeqCli.Mapping; using SeqCli.Util; using Serilog; diff --git a/src/SeqCli/Cli/Commands/IngestCommand.cs b/src/SeqCli/Cli/Commands/IngestCommand.cs index d356212e..3eb2f822 100644 --- a/src/SeqCli/Cli/Commands/IngestCommand.cs +++ b/src/SeqCli/Cli/Commands/IngestCommand.cs @@ -20,7 +20,7 @@ using SeqCli.Cli.Features; using SeqCli.Config; using SeqCli.Ingestion; -using SeqCli.Levels; +using SeqCli.Mapping; using SeqCli.PlainText; using SeqCli.Syntax; using Serilog; diff --git a/src/SeqCli/Cli/Commands/SearchCommand.cs b/src/SeqCli/Cli/Commands/SearchCommand.cs index adea7806..41a7539b 100644 --- a/src/SeqCli/Cli/Commands/SearchCommand.cs +++ b/src/SeqCli/Cli/Commands/SearchCommand.cs @@ -21,7 +21,7 @@ using SeqCli.Api; using SeqCli.Cli.Features; using SeqCli.Config; -using SeqCli.Levels; +using SeqCli.Mapping; using SeqCli.Util; using Serilog; using Serilog.Events; diff --git a/src/SeqCli/Ingestion/JsonLogEventReader.cs b/src/SeqCli/Ingestion/JsonLogEventReader.cs index 07a3ab85..7d5d9d90 100644 --- a/src/SeqCli/Ingestion/JsonLogEventReader.cs +++ b/src/SeqCli/Ingestion/JsonLogEventReader.cs @@ -18,7 +18,7 @@ using System.Threading.Tasks; using Newtonsoft.Json; using Newtonsoft.Json.Linq; -using SeqCli.Levels; +using SeqCli.Mapping; using SeqCli.PlainText.Framing; using Serilog.Events; using Serilog.Formatting.Compact.Reader; diff --git a/src/SeqCli/Levels/LevelMapping.cs b/src/SeqCli/Mapping/LevelMapping.cs similarity index 99% rename from src/SeqCli/Levels/LevelMapping.cs rename to src/SeqCli/Mapping/LevelMapping.cs index f74b7523..99d16aa8 100644 --- a/src/SeqCli/Levels/LevelMapping.cs +++ b/src/SeqCli/Mapping/LevelMapping.cs @@ -16,7 +16,7 @@ using System.Collections.Generic; using Serilog.Events; -namespace SeqCli.Levels; +namespace SeqCli.Mapping; public static class LevelMapping { diff --git a/src/SeqCli/Mapping/MetricsMapping.cs b/src/SeqCli/Mapping/MetricsMapping.cs new file mode 100644 index 00000000..2cc979de --- /dev/null +++ b/src/SeqCli/Mapping/MetricsMapping.cs @@ -0,0 +1,9 @@ +using System; + +namespace SeqCli.Mapping; + +public static class MetricsMapping +{ + internal static readonly string SurrogateDefinitionsProperty = $"_SeqcliMetricDefinitions_{Guid.NewGuid():N}"; + internal static readonly string SurrogateSamplesProperty = $"_SeqcliMetricSamples_{Guid.NewGuid():N}"; +} diff --git a/src/SeqCli/Output/OutputFormatter.cs b/src/SeqCli/Output/OutputFormatter.cs index 9c0c2914..f90389d2 100644 --- a/src/SeqCli/Output/OutputFormatter.cs +++ b/src/SeqCli/Output/OutputFormatter.cs @@ -1,5 +1,5 @@ using SeqCli.Ingestion; -using SeqCli.Levels; +using SeqCli.Mapping; using Serilog.Formatting; using Serilog.Templates; using Serilog.Templates.Themes; @@ -12,7 +12,14 @@ static class OutputFormatter // the `@sp` property, because it needs to load on older Seq installs with older Serilog versions embedded in the // app runner. Once we've updated it, we can switch this to a Seq.Syntax template. internal static ITextFormatter Json(TemplateTheme? theme) => new ExpressionTemplate( - $"{{ {{@t, @mt, @l: coalesce({LevelMapping.SurrogateLevelProperty}, if @l = 'Information' then undefined() else @l), @x, @sp, @tr, @ps: coalesce({TraceConstants.ParentSpanIdProperty}, @ps), @st: coalesce({TraceConstants.SpanStartTimestampProperty}, @st), ..rest()}} }}\n", + $"{{ " + + $"if {MetricsMapping.SurrogateDefinitionsProperty} is not null then " + + // Emit a metric sample + $"{{@t, @l: undefined(), @d: {MetricsMapping.SurrogateDefinitionsProperty}, ..{MetricsMapping.SurrogateSamplesProperty}, ..rest()}} " + + $"else " + + // Emit a log or span + $"{{@t, @mt, @l: coalesce({LevelMapping.SurrogateLevelProperty}, if @l = 'Information' then undefined() else @l), @x, @sp, @tr, @ps: coalesce({TraceConstants.ParentSpanIdProperty}, @ps), @st: coalesce({TraceConstants.SpanStartTimestampProperty}, @st), ..rest()}} " + + $"}}\n", theme: theme ); } diff --git a/src/SeqCli/PlainText/Extraction/Matchers.cs b/src/SeqCli/PlainText/Extraction/Matchers.cs index a70623af..c2326f01 100644 --- a/src/SeqCli/PlainText/Extraction/Matchers.cs +++ b/src/SeqCli/PlainText/Extraction/Matchers.cs @@ -3,7 +3,7 @@ using System.Globalization; using System.Linq; using System.Reflection; -using SeqCli.Levels; +using SeqCli.Mapping; using SeqCli.PlainText.Parsers; using Superpower; using Superpower.Model; diff --git a/src/SeqCli/PlainText/LogEvents/LogEventBuilder.cs b/src/SeqCli/PlainText/LogEvents/LogEventBuilder.cs index 365a490a..bab68619 100644 --- a/src/SeqCli/PlainText/LogEvents/LogEventBuilder.cs +++ b/src/SeqCli/PlainText/LogEvents/LogEventBuilder.cs @@ -17,7 +17,7 @@ using System.Diagnostics; using System.Globalization; using System.Linq; -using SeqCli.Levels; +using SeqCli.Mapping; using SeqCli.Util; using Serilog.Events; using Serilog.Parsing; diff --git a/src/SeqCli/Sample/Loader/Simulation.cs b/src/SeqCli/Sample/Loader/Simulation.cs index b3fc062f..60e9c060 100644 --- a/src/SeqCli/Sample/Loader/Simulation.cs +++ b/src/SeqCli/Sample/Loader/Simulation.cs @@ -14,8 +14,10 @@ using System.Threading; using System.Threading.Tasks; +using Roastery.Metrics; using Seq.Api; using SeqCli.Ingestion; +using SeqCli.Mapping; using Serilog; namespace SeqCli.Sample.Loader; @@ -37,7 +39,7 @@ public static async Task RunAsync(SeqConnection connection, string? apiKey, int var ship = Task.Run(() => LogShipper.ShipEventsAsync(connection, apiKey, buffer, InvalidDataHandling.Fail, SendFailureHandling.Continue, batchSize, null, cancellationToken), cancellationToken); - await Roastery.Program.Main(logger, cancellationToken); + await Roastery.Program.Main(logger, new PropertyNameMapping(MetricsMapping.SurrogateDefinitionsProperty, MetricsMapping.SurrogateSamplesProperty), cancellationToken); await logger.DisposeAsync(); await ship; } diff --git a/test/SeqCli.Tests/PlainText/LogEventBuilderTests.cs b/test/SeqCli.Tests/PlainText/LogEventBuilderTests.cs index 238680fc..75eaf8d5 100644 --- a/test/SeqCli.Tests/PlainText/LogEventBuilderTests.cs +++ b/test/SeqCli.Tests/PlainText/LogEventBuilderTests.cs @@ -1,7 +1,6 @@ using System; using System.Collections.Generic; using System.Linq; -using SeqCli.Levels; using SeqCli.PlainText.LogEvents; using Serilog.Events; using Superpower.Model;