From a5786fcfebe56936c78b54bd56531170818f4c4a Mon Sep 17 00:00:00 2001 From: Echways Date: Wed, 30 Sep 2026 00:21:25 +0300 Subject: [PATCH] integration fixes --- docs/guides/analysis/README.md | 5 ++ docs/guides/analysis/README.ru.md | 6 ++ docs/guides/hosting/README.md | 16 ++-- docs/guides/hosting/README.ru.md | 17 +++-- docs/reference/opentelemetry/README.md | 6 +- docs/reference/opentelemetry/README.ru.md | 6 +- .../Analyzers/CallTreeBuilder.cs | 11 ++- .../EmberTraceOptionsValidator.cs | 8 +- .../Hosting/EmberTraceHostedService.cs | 9 ++- .../Http/EmberTraceMiddleware.cs | 25 ++++--- .../Recording/SlowRequestCapture.cs | 74 +++++++++++++------ src/EmberTrace/Sessions/ScopeReader.cs | 18 ++--- src/EmberTrace/Sessions/TraceSession.cs | 22 +----- src/EmberTrace/Tracing/Profiler.cs | 11 ++- .../EmberTraceOptionsValidatorTests.cs | 5 +- .../Hosting/EmberTraceHostedServiceTests.cs | 24 +++++- .../Http/EmberTraceMiddlewareTests.cs | 27 +++++++ .../Recording/SlowRequestCaptureTests.cs | 72 ++++++++++++++---- .../TestOptionsMonitor.cs | 12 ++- .../Analysis/CallTreeTests.cs | 13 ++++ .../ReportText/CollapsedStackTests.cs | 48 +++++++++++- .../Sessions/SessionClockTests.cs | 49 ++++++------ .../TestSupport/ManualTimeProvider.cs | 11 +++ .../TestSupport/TraceScript.cs | 16 +++- 24 files changed, 371 insertions(+), 140 deletions(-) create mode 100644 tests/EmberTrace.Tests/TestSupport/ManualTimeProvider.cs diff --git a/docs/guides/analysis/README.md b/docs/guides/analysis/README.md index 78fcac5..f0fedc4 100644 --- a/docs/guides/analysis/README.md +++ b/docs/guides/analysis/README.md @@ -102,6 +102,11 @@ using var file = File.CreateText("out/trace.folded"); TraceText.WriteCollapsedStacks(session.Process(), file, Tracer.CreateMetadata()); ``` +In a snapshot, scopes still open at the cut are weighed up to the cut, so an in-flight request shows the time it has +spent so far; hotspots and percentiles count only finished scopes. Scopes that began before the snapshot's window +are missing — widen the window to see them. Concurrent async children are each weighed by their own time, so a +parent that fans out with `Task.WhenAll` is drawn wider than it ran. + ## Screenshots ![Analysis slice: aggregation, sorting, filters](../../assets/analysis-slice.png) diff --git a/docs/guides/analysis/README.ru.md b/docs/guides/analysis/README.ru.md index 79f8bff..b3e7ff1 100644 --- a/docs/guides/analysis/README.ru.md +++ b/docs/guides/analysis/README.ru.md @@ -102,6 +102,12 @@ using var file = File.CreateText("out/trace.folded"); TraceText.WriteCollapsedStacks(session.Process(), file, Tracer.CreateMetadata()); ``` +В снапшоте скоупы, открытые на момент среза, учитываются до среза, поэтому запрос, который ещё выполняется, виден +со временем, потраченным на данный момент; hotspots и перцентили считают только завершённые скоупы. Скоупов, +начавшихся до окна снапшота, в нём нет — расширьте окно, чтобы их увидеть. Параллельные асинхронные дочерние скоупы +учитываются каждый со своим временем, поэтому родитель, распараллеливший работу через `Task.WhenAll`, рисуется шире, +чем выполнялся. + ## Скриншоты ![Срез анализа: агрегирование/сортировка/фильтры](../../assets/analysis-slice.png) diff --git a/docs/guides/hosting/README.md b/docs/guides/hosting/README.md index 7d522d3..08efdc5 100644 --- a/docs/guides/hosting/README.md +++ b/docs/guides/hosting/README.md @@ -100,7 +100,7 @@ Categories are configured by name and hashed into ids the same way `Tracer.Categ ## What the middleware records -For each request that is not on `IgnoredPaths`: +For each request that is not on `IgnoredPaths` and not addressed to the dump endpoint's `Path`: - an async scope named `"{METHOD} {route pattern}"`, e.g. `GET /orders/{id}`; ids are bounded by `MaxTrackedRoutes`, and once that cap is reached new routes collapse onto `HTTP {METHOD}`; @@ -162,12 +162,14 @@ would be. ## Slow request capture -With `SlowRequests:Enabled`, a request that runs longer than `Threshold` makes EmberTrace write the last `Window` of -the flight recorder to `Directory` as `{prefix}-slow-{timestamp}.ember`. Requests that throw count too. One capture -opens a `Cooldown` during which further slow requests are ignored, so a latency incident produces one file, not -thousands. The snapshot and the write happen on the thread pool; the slow request is not delayed further, and a failed -write is logged, never thrown. `Window` must be zero (the whole buffer) or at least `Threshold`, and request recording -must stay enabled. +With `SlowRequests:Enabled`, a request that runs longer than `Threshold` makes EmberTrace write a snapshot of the +flight recorder to `Directory` as `{prefix}-slow-{timestamp}.ember`. The snapshot covers the last `Window`, stretched +when needed so that the slow request is in it from its first event; a `Window` of zero takes the whole buffer. +Requests that throw count too. A written capture opens a `Cooldown` of at least one millisecond during which further +slow requests are ignored, so a latency incident produces one file, not thousands; a capture that found nothing to +write, or failed, does not open one. Captures run on the thread pool one at a time: the slow request is not delayed +further, a failed write is logged, never thrown, and graceful shutdown waits for a capture in progress. Request +recording must stay enabled. ## Session lifetime diff --git a/docs/guides/hosting/README.ru.md b/docs/guides/hosting/README.ru.md index 851d908..bb6f2f9 100644 --- a/docs/guides/hosting/README.ru.md +++ b/docs/guides/hosting/README.ru.md @@ -100,7 +100,7 @@ builder.Services.AddEmberTrace(builder.Configuration.GetSection("Tracing")); ## Что записывает middleware -Для каждого запроса, не попавшего в `IgnoredPaths`: +Для каждого запроса, не попавшего в `IgnoredPaths` и не адресованного `Path` эндпоинта дампа: - асинхронный скоуп с именем `"{METHOD} {шаблон маршрута}"`, например `GET /orders/{id}`; количество идентификаторов ограничено `MaxTrackedRoutes`, и после достижения лимита новые маршруты схлопываются @@ -164,12 +164,15 @@ endpoint не сообщает о своём существовании; `401` ## Захват медленных запросов -С `SlowRequests:Enabled` запрос, который выполняется дольше `Threshold`, заставляет EmberTrace записать последние -`Window` flight recorder'а в `Directory` как `{prefix}-slow-{timestamp}.ember`. Запросы, завершившиеся исключением, -тоже учитываются. Один захват открывает `Cooldown`, в течение которого следующие медленные запросы игнорируются, так -что инцидент с задержками даёт один файл, а не тысячи. Снапшот и запись выполняются в пуле потоков: медленный запрос -не замедляется ещё больше, а ошибка записи логируется и никогда не выбрасывается. `Window` должен быть нулём (весь -буфер) или не короче `Threshold`, а запись запросов должна оставаться включённой. +С `SlowRequests:Enabled` запрос, который выполняется дольше `Threshold`, заставляет EmberTrace записать снапшот +flight recorder'а в `Directory` как `{prefix}-slow-{timestamp}.ember`. Снапшот охватывает последние `Window` и при +необходимости растягивается так, чтобы медленный запрос попал в него целиком, с первого события; `Window`, равный +нулю, берёт весь буфер. Запросы, завершившиеся исключением, тоже учитываются. Записанный захват открывает `Cooldown` +не короче одной миллисекунды, в течение которого следующие медленные запросы игнорируются, так что инцидент с +задержками даёт один файл, а не тысячи; захват, которому нечего было записать или который завершился ошибкой, +`Cooldown` не открывает. Захваты выполняются в пуле потоков по одному: медленный запрос не замедляется ещё больше, +ошибка записи логируется и никогда не выбрасывается, а корректная остановка хоста дожидается захвата, который уже +идёт. Запись запросов должна оставаться включённой. ## Жизненный цикл сессии diff --git a/docs/reference/opentelemetry/README.md b/docs/reference/opentelemetry/README.md index 8cff78f..bd79acb 100644 --- a/docs/reference/opentelemetry/README.md +++ b/docs/reference/opentelemetry/README.md @@ -29,8 +29,10 @@ foreach (var span in spans) `OpenTelemetryExportOptions`: - `IncludeFlowsAsLinks` - include Flow as links - `IncludeThreadIdTag` - include `thread.id` -- `BaseUtc` - UTC time of the session start. Defaults to `TraceSession.StartedAtUtc`, which is recorded by - `Tracer.Start` and stored in `.ember` files; only sessions without it fall back to "now minus the session duration". +- `BaseUtc` - UTC time of the session start. Defaults to `TraceSession.StartedAtUtc`: `Tracer.Start` records it for + the session, and a snapshot derives its own from the wall clock at the moment it is cut, so its spans line up with + logs written at that moment. It is stored in `.ember` files; only sessions without it fall back to "now minus the + session duration". ## Notes diff --git a/docs/reference/opentelemetry/README.ru.md b/docs/reference/opentelemetry/README.ru.md index 4301524..6bec323 100644 --- a/docs/reference/opentelemetry/README.ru.md +++ b/docs/reference/opentelemetry/README.ru.md @@ -29,8 +29,10 @@ foreach (var span in spans) `OpenTelemetryExportOptions`: - `IncludeFlowsAsLinks` — добавить Flow как links - `IncludeThreadIdTag` — добавить `thread.id` -- `BaseUtc` — UTC‑время начала сессии. По умолчанию берётся `TraceSession.StartedAtUtc`, который записывает - `Tracer.Start` и сохраняет `.ember`; только сессии без него откатываются к «сейчас минус длительность сессии». +- `BaseUtc` — UTC‑время начала сессии. По умолчанию берётся `TraceSession.StartedAtUtc`: для сессии его записывает + `Tracer.Start`, а снапшот выводит своё из системных часов в момент среза, поэтому его спаны совпадают с логами, + записанными в тот же момент. Значение сохраняется в `.ember`; только сессии без него откатываются к «сейчас минус + длительность сессии». ## Примечания diff --git a/src/EmberTrace.Analysis/Analyzers/CallTreeBuilder.cs b/src/EmberTrace.Analysis/Analyzers/CallTreeBuilder.cs index 01ea0ec..dd5bbda 100644 --- a/src/EmberTrace.Analysis/Analyzers/CallTreeBuilder.cs +++ b/src/EmberTrace.Analysis/Analyzers/CallTreeBuilder.cs @@ -26,7 +26,7 @@ public static ProcessedTrace Process(TraceSession session, bool strict, bool gro continue; } - if (step.IsSynthetic || step.Tag is not TreeFrame frame) + if (step.Tag is not TreeFrame frame || (step.IsSynthetic && !session.IsSnapshot)) continue; var inclusive = step.DurationTicks; @@ -40,6 +40,12 @@ public static ProcessedTrace Process(TraceSession session, bool strict, bool gro frame.Node.InclusiveTicks += inclusive; frame.Node.ExclusiveTicks += exclusive; + if (step.ParentTag is TreeFrame parentFrame) + parentFrame.ChildTicks += inclusive; + + if (step.IsSynthetic) + continue; + if (!hotspots.TryGetValue(step.Id, out var agg)) { agg = new HotAgg(session.TimestampFrequency); @@ -50,9 +56,6 @@ public static ProcessedTrace Process(TraceSession session, bool strict, bool gro agg.InclusiveTicks += inclusive; agg.ExclusiveTicks += exclusive; agg.Histogram.Add(inclusive); - - if (step.ParentTag is TreeFrame parentFrame) - parentFrame.ChildTicks += inclusive; } foreach (var track in reader.Tracks) diff --git a/src/EmberTrace.Extensions.Hosting/Configuration/EmberTraceOptionsValidator.cs b/src/EmberTrace.Extensions.Hosting/Configuration/EmberTraceOptionsValidator.cs index 752f43c..499c513 100644 --- a/src/EmberTrace.Extensions.Hosting/Configuration/EmberTraceOptionsValidator.cs +++ b/src/EmberTrace.Extensions.Hosting/Configuration/EmberTraceOptionsValidator.cs @@ -50,11 +50,11 @@ private static void ValidateSlowRequests(EmberTraceOptions options, List if (slow.Threshold <= TimeSpan.Zero) failures.Add("EmberTrace:SlowRequests:Threshold must be greater than zero."); - if (slow.Cooldown < TimeSpan.Zero) - failures.Add("EmberTrace:SlowRequests:Cooldown cannot be negative."); + if (slow.Cooldown < TimeSpan.FromMilliseconds(1)) + failures.Add("EmberTrace:SlowRequests:Cooldown must be at least one millisecond."); - if (slow.Window < TimeSpan.Zero || (slow.Window > TimeSpan.Zero && slow.Window < slow.Threshold)) - failures.Add("EmberTrace:SlowRequests:Window must be zero or at least as long as the threshold."); + if (slow.Window < TimeSpan.Zero) + failures.Add("EmberTrace:SlowRequests:Window cannot be negative."); if (!options.Requests.Enabled) failures.Add("EmberTrace:SlowRequests requires EmberTrace:Requests:Enabled."); diff --git a/src/EmberTrace.Extensions.Hosting/Hosting/EmberTraceHostedService.cs b/src/EmberTrace.Extensions.Hosting/Hosting/EmberTraceHostedService.cs index ec499a1..86f51d6 100644 --- a/src/EmberTrace.Extensions.Hosting/Hosting/EmberTraceHostedService.cs +++ b/src/EmberTrace.Extensions.Hosting/Hosting/EmberTraceHostedService.cs @@ -9,18 +9,21 @@ namespace EmberTrace.Extensions.Hosting; internal sealed class EmberTraceHostedService : IHostedService { + private readonly SlowRequestCapture _capture; private readonly ILogger _logger; private readonly EmberTraceOptions _options; private readonly EmberTraceRecorder _recorder; public EmberTraceHostedService( EmberTraceRecorder recorder, + SlowRequestCapture capture, IOptions options, ILogger logger) { ArgumentNullException.ThrowIfNull(options); _recorder = recorder ?? throw new ArgumentNullException(nameof(recorder)); + _capture = capture ?? throw new ArgumentNullException(nameof(capture)); _options = options.Value; _logger = logger ?? throw new ArgumentNullException(nameof(logger)); } @@ -31,13 +34,13 @@ public Task StartAsync(CancellationToken cancellationToken) return Task.CompletedTask; } - public Task StopAsync(CancellationToken cancellationToken) + public async Task StopAsync(CancellationToken cancellationToken) { + await _capture.DrainAsync(cancellationToken); + var session = _recorder.TryStop(); if (session is not null) WriteShutdownDump(session); - - return Task.CompletedTask; } private void WriteShutdownDump(TraceSession session) diff --git a/src/EmberTrace.Extensions.Hosting/Http/EmberTraceMiddleware.cs b/src/EmberTrace.Extensions.Hosting/Http/EmberTraceMiddleware.cs index 53907be..4dd42dc 100644 --- a/src/EmberTrace.Extensions.Hosting/Http/EmberTraceMiddleware.cs +++ b/src/EmberTrace.Extensions.Hosting/Http/EmberTraceMiddleware.cs @@ -26,14 +26,16 @@ public async Task InvokeAsync(HttpContext context) { ArgumentNullException.ThrowIfNull(context); - var requests = _options.CurrentValue.Requests; + var options = _options.CurrentValue; + var requests = options.Requests; - if (!requests.Enabled || !Tracer.IsRunning || IsIgnored(context.Request.Path, requests.IgnoredPaths)) + if (!requests.Enabled || !Tracer.IsRunning || IsIgnored(context.Request.Path, options)) { await _next(context); return; } + var started = Stopwatch.GetTimestamp(); var id = ResolveId(context, requests); var flowId = requests.RecordFlow ? ResolveFlowId() : 0; @@ -43,15 +45,13 @@ public async Task InvokeAsync(HttpContext context) Tracer.FlowStart(id, flowId); } - var started = Stopwatch.GetTimestamp(); - try { await InvokeTracedAsync(context, id, flowId); } finally { - CaptureIfSlow(context, id, Stopwatch.GetElapsedTime(started)); + CaptureIfSlow(context, options, id, started); } } @@ -71,14 +71,14 @@ private async Task InvokeTracedAsync(HttpContext context, int id, long flowId) } } - private void CaptureIfSlow(HttpContext context, int id, TimeSpan elapsed) + private static void CaptureIfSlow(HttpContext context, EmberTraceOptions options, int id, long started) { - var slow = _options.CurrentValue.SlowRequests; - if (!slow.Enabled || elapsed < slow.Threshold) + var elapsed = Stopwatch.GetElapsedTime(started); + if (!options.SlowRequests.Enabled || elapsed < options.SlowRequests.Threshold) return; var request = HttpTraceIds.Provider.TryGet(id, out var meta) ? meta.Name : context.Request.Path.Value ?? "/"; - context.RequestServices?.GetService()?.TryCapture(request, elapsed); + context.RequestServices?.GetService()?.TryCapture(options, request, started, elapsed); } private static int ResolveId(HttpContext context, EmberTraceRequestOptions requests) @@ -103,8 +103,13 @@ private static long ResolveFlowId() return ActivityFlow.TryGetCurrentFlowId(out var flowId) ? flowId : Tracer.NewFlowId(); } - private static bool IsIgnored(PathString path, string[] ignored) + private static bool IsIgnored(PathString path, EmberTraceOptions options) { + var dump = options.Dump; + if (dump.Enabled && path.StartsWithSegments(new PathString(dump.Path), StringComparison.OrdinalIgnoreCase)) + return true; + + var ignored = options.Requests.IgnoredPaths; for (var i = 0; i < ignored.Length; i++) { var candidate = ignored[i]; diff --git a/src/EmberTrace.Extensions.Hosting/Recording/SlowRequestCapture.cs b/src/EmberTrace.Extensions.Hosting/Recording/SlowRequestCapture.cs index 92dd790..03bd8fe 100644 --- a/src/EmberTrace.Extensions.Hosting/Recording/SlowRequestCapture.cs +++ b/src/EmberTrace.Extensions.Hosting/Recording/SlowRequestCapture.cs @@ -1,56 +1,84 @@ +using System.Diagnostics; using EmberTrace.Extensions.Hosting.Configuration; using EmberTrace.Sessions; using Microsoft.Extensions.Logging; -using Microsoft.Extensions.Options; namespace EmberTrace.Extensions.Hosting.Recording; -internal sealed class SlowRequestCapture( - IOptionsMonitor options, - ILogger logger, - TimeProvider time) +internal sealed class SlowRequestCapture(ILogger logger, TimeProvider time) { + private int _busy; private long _nextAllowedUtcTicks = long.MinValue; + private Task _pending = Task.CompletedTask; - public Task? TryCapture(string request, TimeSpan elapsed) + public Task? TryCapture(EmberTraceOptions options, string request, long startTimestamp, TimeSpan elapsed) { - var current = options.CurrentValue; - var slow = current.SlowRequests; + var slow = options.SlowRequests; - if (!slow.Enabled || !Tracer.IsRunning) + if (!slow.Enabled || !Tracer.IsRunning || Interlocked.Exchange(ref _busy, 1) == 1) return null; var now = time.GetUtcNow(); - var allowedFrom = Volatile.Read(ref _nextAllowedUtcTicks); + var previous = _nextAllowedUtcTicks; - if (now.UtcTicks < allowedFrom - || Interlocked.CompareExchange(ref _nextAllowedUtcTicks, (now + slow.Cooldown).UtcTicks, allowedFrom) - != allowedFrom) + if (now.UtcTicks < previous) + { + Volatile.Write(ref _busy, 0); return null; + } + + _nextAllowedUtcTicks = (now + slow.Cooldown).UtcTicks; var path = Path.Combine(slow.Directory!, - DumpFileName.Create(current.Dump.FileNamePrefix, "slow", now, TraceFormat.FileExtension)); + DumpFileName.Create(options.Dump.FileNamePrefix, "slow", now, TraceFormat.FileExtension)); + var window = slow.Window; - return Task.Run(() => Write(Tracer.Snapshot(slow.Window), path, request, elapsed)); + var capture = Task.Run(() => Capture(window, startTimestamp, path, request, elapsed, previous)); + Volatile.Write(ref _pending, capture); + return capture; + } + + public async Task DrainAsync(CancellationToken cancellationToken) + { + await Volatile.Read(ref _pending) + .WaitAsync(cancellationToken) + .ConfigureAwait(ConfigureAwaitOptions.SuppressThrowing); } - private void Write(TraceSession session, string path, string request, TimeSpan elapsed) + private void Capture(TimeSpan window, long startTimestamp, string path, string request, TimeSpan elapsed, + long previous) { - if (session.EventCount == 0) - return; + var written = false; try { - TraceFormat.Write(session, path); - logger.LogWarning("EmberTrace captured {Request} ({Elapsed}) to {Path}.", request, elapsed, path); + var session = Tracer.Snapshot(WindowFor(window, startTimestamp)); + if (session.EventCount > 0) + { + TraceFormat.Write(session, path); + written = true; + logger.LogWarning("EmberTrace captured {Request} ({Elapsed}) to {Path}.", request, elapsed, path); + } } - catch (IOException ex) + catch (Exception ex) { logger.LogError(ex, "EmberTrace could not write the slow request capture to {Path}.", path); } - catch (UnauthorizedAccessException ex) + finally { - logger.LogError(ex, "EmberTrace could not write the slow request capture to {Path}.", path); + if (!written) + _nextAllowedUtcTicks = previous; + + Volatile.Write(ref _busy, 0); } } + + private static TimeSpan WindowFor(TimeSpan window, long startTimestamp) + { + if (window == TimeSpan.Zero) + return TimeSpan.Zero; + + var sinceStart = Stopwatch.GetElapsedTime(startTimestamp); + return sinceStart > window ? sinceStart : window; + } } diff --git a/src/EmberTrace/Sessions/ScopeReader.cs b/src/EmberTrace/Sessions/ScopeReader.cs index 59f7a5e..b4fcd82 100644 --- a/src/EmberTrace/Sessions/ScopeReader.cs +++ b/src/EmberTrace/Sessions/ScopeReader.cs @@ -214,22 +214,16 @@ public IEnumerable Read() yield return new ScopeStep(ScopeStepKind.Close, top, e.TrackId, e.ThreadId, e.Timestamp, false); } + var open = new List(asyncFrames.Values); foreach (var kv in tracks) - { - var track = kv.Value; - for (var i = track.Count - 1; i >= 0; i--) - { - UnmatchedBeginCount++; - yield return new ScopeStep(ScopeStepKind.Close, track[i], track[i].TrackId, track[i].ThreadId, - _endTimestamp, true); - } - } + open.AddRange(kv.Value); + + open.Sort(static (a, b) => b.Index.CompareTo(a.Index)); - foreach (var kv in asyncFrames) + foreach (var frame in open) { UnmatchedBeginCount++; - yield return new ScopeStep(ScopeStepKind.Close, kv.Value, kv.Value.TrackId, kv.Value.ThreadId, - _endTimestamp, true); + yield return new ScopeStep(ScopeStepKind.Close, frame, frame.TrackId, frame.ThreadId, _endTimestamp, true); } } diff --git a/src/EmberTrace/Sessions/TraceSession.cs b/src/EmberTrace/Sessions/TraceSession.cs index ea4799b..124dbfe 100644 --- a/src/EmberTrace/Sessions/TraceSession.cs +++ b/src/EmberTrace/Sessions/TraceSession.cs @@ -51,26 +51,8 @@ public static TraceSession FromEvents( long sampledOutEvents = 0, bool wasOverflow = false, SessionOptions? options = null, - bool isSnapshot = false) - { - return FromEvents(events, startTimestamp, endTimestamp, timestampFrequency, threadNames, metadata, - droppedEvents, droppedChunks, sampledOutEvents, wasOverflow, options, isSnapshot, null); - } - - internal static TraceSession FromEvents( - IEnumerable events, - long startTimestamp, - long endTimestamp, - long timestampFrequency, - IReadOnlyDictionary? threadNames, - ITraceMetadataProvider? metadata, - long droppedEvents, - long droppedChunks, - long sampledOutEvents, - bool wasOverflow, - SessionOptions? options, - bool isSnapshot, - DateTimeOffset? startedAtUtc) + bool isSnapshot = false, + DateTimeOffset? startedAtUtc = null) { ArgumentNullException.ThrowIfNull(events); diff --git a/src/EmberTrace/Tracing/Profiler.cs b/src/EmberTrace/Tracing/Profiler.cs index 1ca3465..6f2230f 100644 --- a/src/EmberTrace/Tracing/Profiler.cs +++ b/src/EmberTrace/Tracing/Profiler.cs @@ -16,12 +16,18 @@ internal sealed class Profiler [ThreadStatic] private static long _cachedSessionId; [ThreadStatic] private static ThreadWriter? _cachedWriter; + private readonly TimeProvider _clock; private int _enabled; private ITraceMetadataProvider? _metadata; private long _nextFlowId; private RuntimeCounterSampler? _runtimeSampler; private ProfilingState? _state; + public Profiler(TimeProvider? clock = null) + { + _clock = clock ?? TimeProvider.System; + } + public bool IsRunning => Volatile.Read(ref _enabled) == 1; public ITraceMetadataProvider Metadata => _metadata ?? TraceMetadata.CreateDefault(); @@ -53,7 +59,7 @@ public void Start(SessionOptions? options = null) _metadata = meta; _state = new ProfilingState(opts, collector, meta, categoryFilter, sampling, Timestamp.Now(), - DateTimeOffset.UtcNow); + _clock.GetUtcNow()); if (opts.RuntimeCounters != RuntimeCounters.None) { @@ -119,6 +125,7 @@ public TraceSession Snapshot(TimeSpan window) try { var cut = Timestamp.Now(); + var cutUtc = _clock.GetUtcNow(); var min = WindowStart(cut, window); var chunks = SnapshotBuilder.Copy(captures, min, out var discarded); collector.RecordSnapshotDiscard(discarded); @@ -138,7 +145,7 @@ public TraceSession Snapshot(TimeSpan window) state.Metadata, 0, true, - state.StartedAtUtc + Stopwatch.GetElapsedTime(state.StartTs, start)); + cutUtc - Stopwatch.GetElapsedTime(start, cut)); } finally { diff --git a/tests/EmberTrace.Extensions.Hosting.Tests/Configuration/EmberTraceOptionsValidatorTests.cs b/tests/EmberTrace.Extensions.Hosting.Tests/Configuration/EmberTraceOptionsValidatorTests.cs index 2ad8cce..526a1ad 100644 --- a/tests/EmberTrace.Extensions.Hosting.Tests/Configuration/EmberTraceOptionsValidatorTests.cs +++ b/tests/EmberTrace.Extensions.Hosting.Tests/Configuration/EmberTraceOptionsValidatorTests.cs @@ -19,6 +19,7 @@ [new EmberTraceOptions()], [new EmberTraceOptions { Dump = { Path = "relative", ApiKey = "short", MaxWindow = TimeSpan.Zero } }], [SlowRequests(slow => slow.Directory = "/var/tmp/embertrace")], [SlowRequests(slow => slow.Window = TimeSpan.Zero)], + [SlowRequests(slow => slow.Window = TimeSpan.FromMilliseconds(10))], [new EmberTraceOptions { SlowRequests = { Threshold = TimeSpan.Zero } }] ]; @@ -37,8 +38,8 @@ [new EmberTraceOptions()], [Unguarded(_ => { }), "without a guard"], [SlowRequests(slow => slow.Directory = null), "SlowRequests:Directory"], [SlowRequests(slow => slow.Threshold = TimeSpan.Zero), "SlowRequests:Threshold"], - [SlowRequests(slow => slow.Cooldown = TimeSpan.FromSeconds(-1)), "SlowRequests:Cooldown"], - [SlowRequests(slow => slow.Window = TimeSpan.FromMilliseconds(999)), "SlowRequests:Window"], + [SlowRequests(slow => slow.Cooldown = TimeSpan.Zero), "Cooldown must be at least one millisecond"], + [SlowRequests(slow => slow.Window = TimeSpan.FromSeconds(-1)), "SlowRequests:Window cannot be negative"], [new EmberTraceOptions { SlowRequests = { Enabled = true, Directory = "/tmp" }, Requests = { Enabled = false } }, "requires EmberTrace:Requests:Enabled"] ]; diff --git a/tests/EmberTrace.Extensions.Hosting.Tests/Hosting/EmberTraceHostedServiceTests.cs b/tests/EmberTrace.Extensions.Hosting.Tests/Hosting/EmberTraceHostedServiceTests.cs index 0d87956..5a4ea6a 100644 --- a/tests/EmberTrace.Extensions.Hosting.Tests/Hosting/EmberTraceHostedServiceTests.cs +++ b/tests/EmberTrace.Extensions.Hosting.Tests/Hosting/EmberTraceHostedServiceTests.cs @@ -1,3 +1,4 @@ +using System.Diagnostics; using EmberTrace.Extensions.Hosting.Configuration; using EmberTrace.Extensions.Hosting.Recording; using EmberTrace.Sessions; @@ -90,10 +91,29 @@ public async Task DisabledRecorder_NeitherStartsNorStops() Assert.IsFalse(Directory.Exists(_directory)); } - private static EmberTraceHostedService Create(EmberTraceOptions options) + [TestMethod] + public async Task StopAsync_WaitsForACaptureInProgress() + { + var options = new EmberTraceOptions { SlowRequests = { Enabled = true, Directory = _directory } }; + var capture = new SlowRequestCapture(NullLogger.Instance, TimeProvider.System); + var service = Create(options, capture); + await service.StartAsync(CancellationToken.None); + Tracer.Instant(Tracer.Id("drain-probe")); + + _ = capture.TryCapture(options, "GET /a", Stopwatch.GetTimestamp(), TimeSpan.FromSeconds(2)); + await service.StopAsync(CancellationToken.None); + + Assert.HasCount(1, Directory.GetFiles(_directory)); + } + + private static EmberTraceHostedService Create(EmberTraceOptions options, SlowRequestCapture? capture = null) { var wrapped = Options.Create(options); var recorder = new EmberTraceRecorder(wrapped, NullLogger.Instance); - return new EmberTraceHostedService(recorder, wrapped, NullLogger.Instance); + return new EmberTraceHostedService( + recorder, + capture ?? new SlowRequestCapture(NullLogger.Instance, TimeProvider.System), + wrapped, + NullLogger.Instance); } } diff --git a/tests/EmberTrace.Extensions.Hosting.Tests/Http/EmberTraceMiddlewareTests.cs b/tests/EmberTrace.Extensions.Hosting.Tests/Http/EmberTraceMiddlewareTests.cs index 15adc2f..29a4229 100644 --- a/tests/EmberTrace.Extensions.Hosting.Tests/Http/EmberTraceMiddlewareTests.cs +++ b/tests/EmberTrace.Extensions.Hosting.Tests/Http/EmberTraceMiddlewareTests.cs @@ -240,6 +240,33 @@ public async Task SlowRequest_IsCapturedEvenWhenItThrows_AndFastOnesAreNot(bool } } + [TestMethod] + public async Task OptionsBrokenMidRequest_DoNotMaskTheApplicationException() + { + var monitor = new TestOptionsMonitor(new EmberTraceOptions()); + var middleware = new EmberTraceMiddleware(_ => + { + monitor.Failure = new OptionsValidationException(string.Empty, typeof(EmberTraceOptions), ["reloaded"]); + throw new InvalidOperationException("boom"); + }, monitor); + + await Assert.ThrowsExactlyAsync( + () => middleware.InvokeAsync(Request("GET", "/orders/17", "/orders/{id}"))); + } + + [TestMethod] + [DataRow("/diag/trace", false)] + [DataRow("/DIAG/trace", false)] + [DataRow("/diag/other", true)] + public async Task DumpPath_IsNeverTraced(string path, bool traced) + { + var options = new EmberTraceOptions { Dump = { Enabled = true, Path = "/diag/trace" } }; + + await Create(static _ => Task.CompletedTask, options).InvokeAsync(Request("GET", path)); + + Assert.AreEqual(traced, StopAndCollect().Count > 0); + } + private static EmberTraceMiddleware Create(RequestDelegate next, EmberTraceOptions? options = null) { return new EmberTraceMiddleware(next, diff --git a/tests/EmberTrace.Extensions.Hosting.Tests/Recording/SlowRequestCaptureTests.cs b/tests/EmberTrace.Extensions.Hosting.Tests/Recording/SlowRequestCaptureTests.cs index 171c182..d60c92e 100644 --- a/tests/EmberTrace.Extensions.Hosting.Tests/Recording/SlowRequestCaptureTests.cs +++ b/tests/EmberTrace.Extensions.Hosting.Tests/Recording/SlowRequestCaptureTests.cs @@ -1,3 +1,4 @@ +using System.Diagnostics; using EmberTrace.Extensions.Hosting.Configuration; using EmberTrace.Extensions.Hosting.Recording; using EmberTrace.Sessions; @@ -10,6 +11,7 @@ namespace EmberTrace.Extensions.Hosting.Tests.Recording; public sealed class SlowRequestCaptureTests { private static readonly DateTimeOffset Now = new(2026, 9, 15, 10, 0, 0, TimeSpan.Zero); + private static readonly TimeSpan Elapsed = TimeSpan.FromSeconds(2); private readonly ManualTimeProvider _clock = new(Now); private string _directory = null!; @@ -37,7 +39,7 @@ public void Cleanup() [TestMethod] public async Task Capture_WritesASnapshotNamedAfterThePrefixAndTheMoment() { - await Create().TryCapture("GET /orders/{id}", TimeSpan.FromSeconds(2))!; + await Create().TryCapture(Slow(), "GET /orders/{id}", Stopwatch.GetTimestamp(), Elapsed)!; var file = Directory.EnumerateFiles(_directory).Single(); @@ -48,31 +50,65 @@ public async Task Capture_WritesASnapshotNamedAfterThePrefixAndTheMoment() Assert.IsTrue(Tracer.IsRunning); } + [TestMethod] + public async Task Capture_KeepsTheWholeRequestWhenItOutlivesTheWindow() + { + var request = Tracer.Id("slow-request"); + var started = Stopwatch.GetTimestamp(); + using (Tracer.Scope(request)) + Thread.Sleep(200); + + await Create().TryCapture(Slow(window: TimeSpan.FromMilliseconds(50)), "GET /a", started, + Stopwatch.GetElapsedTime(started))!; + + var events = TraceFormat.Read(Directory.EnumerateFiles(_directory).Single()).SortedEvents(); + + CollectionAssert.AreEqual( + new[] { TraceEventKind.Begin, TraceEventKind.End }, + events.Where(e => e.Id == request).Select(e => e.Kind).ToArray()); + } + [TestMethod] public async Task Capture_IsRateLimitedByTheCooldown() { var capture = Create(); - await capture.TryCapture("GET /a", TimeSpan.FromSeconds(2))!; + await capture.TryCapture(Slow(), "GET /a", Stopwatch.GetTimestamp(), Elapsed)!; _clock.Now = Now + TimeSpan.FromSeconds(59); - Assert.IsNull(capture.TryCapture("GET /a", TimeSpan.FromSeconds(2))); + Assert.IsNull(capture.TryCapture(Slow(), "GET /a", Stopwatch.GetTimestamp(), Elapsed)); _clock.Now = Now + TimeSpan.FromSeconds(60); - await capture.TryCapture("GET /b", TimeSpan.FromSeconds(2))!; + await capture.TryCapture(Slow(), "GET /b", Stopwatch.GetTimestamp(), Elapsed)!; Assert.HasCount(2, Directory.EnumerateFiles(_directory).ToList()); } [TestMethod] - public async Task Capture_OfAnEmptySnapshot_WritesNothing() + public async Task Capture_OfAnEmptySnapshot_WritesNothingAndKeepsTheCooldownFree() { Tracer.Stop(); Tracer.Start(new SessionOptions { ChunkCapacity = 1024 }); + var capture = Create(); - await Create().TryCapture("GET /a", TimeSpan.FromSeconds(2))!; - + await capture.TryCapture(Slow(), "GET /a", Stopwatch.GetTimestamp(), Elapsed)!; Assert.IsFalse(Directory.Exists(_directory)); + + Tracer.Instant(_probe); + await capture.TryCapture(Slow(), "GET /a", Stopwatch.GetTimestamp(), Elapsed)!; + + Assert.HasCount(1, Directory.EnumerateFiles(_directory).ToList()); + } + + [TestMethod] + public async Task FailedCapture_NeitherFaultsNorStartsTheCooldown() + { + var capture = Create(); + + await capture.TryCapture(Slow(directory: "bad\0dir"), "GET /a", Stopwatch.GetTimestamp(), Elapsed)!; + await capture.TryCapture(Slow(), "GET /a", Stopwatch.GetTimestamp(), Elapsed)!; + + Assert.HasCount(1, Directory.EnumerateFiles(_directory).ToList()); } [TestMethod] @@ -83,19 +119,27 @@ public void Capture_WhenDisabledOrWithoutASession_DoesNothing(bool enabled, bool if (!running) Tracer.Stop(); - Assert.IsNull(Create(enabled).TryCapture("GET /a", TimeSpan.FromSeconds(2))); + Assert.IsNull(Create().TryCapture(Slow(enabled), "GET /a", Stopwatch.GetTimestamp(), Elapsed)); Assert.IsFalse(Directory.Exists(_directory)); } - private SlowRequestCapture Create(bool enabled = true) + private SlowRequestCapture Create() { - var options = new EmberTraceOptions + return new SlowRequestCapture(NullLogger.Instance, _clock); + } + + private EmberTraceOptions Slow(bool enabled = true, TimeSpan? window = null, string? directory = null) + { + return new EmberTraceOptions { Dump = { FileNamePrefix = "svc" }, - SlowRequests = { Enabled = enabled, Directory = _directory, Cooldown = TimeSpan.FromMinutes(1) } + SlowRequests = + { + Enabled = enabled, + Directory = directory ?? _directory, + Cooldown = TimeSpan.FromMinutes(1), + Window = window ?? TimeSpan.FromSeconds(10) + } }; - - return new SlowRequestCapture(new TestOptionsMonitor(options), - NullLogger.Instance, _clock); } } diff --git a/tests/EmberTrace.Extensions.Hosting.Tests/TestOptionsMonitor.cs b/tests/EmberTrace.Extensions.Hosting.Tests/TestOptionsMonitor.cs index 31c6180..708548f 100644 --- a/tests/EmberTrace.Extensions.Hosting.Tests/TestOptionsMonitor.cs +++ b/tests/EmberTrace.Extensions.Hosting.Tests/TestOptionsMonitor.cs @@ -4,12 +4,20 @@ namespace EmberTrace.Extensions.Hosting.Tests; internal sealed class TestOptionsMonitor : IOptionsMonitor { + private T _value; + public TestOptionsMonitor(T value) { - CurrentValue = value; + _value = value; } - public T CurrentValue { get; set; } + public Exception? Failure { get; set; } + + public T CurrentValue + { + get => Failure is null ? _value : throw Failure; + set => _value = value; + } public T Get(string? name) { diff --git a/tests/EmberTrace.Tests/Analysis/CallTreeTests.cs b/tests/EmberTrace.Tests/Analysis/CallTreeTests.cs index cc8d7a4..2b3b07c 100644 --- a/tests/EmberTrace.Tests/Analysis/CallTreeTests.cs +++ b/tests/EmberTrace.Tests/Analysis/CallTreeTests.cs @@ -94,6 +94,19 @@ public void Process_CarriesSessionCounters() Assert.IsEmpty(trace.GlobalRoot.Children); } + [TestMethod] + public void OpenScopesInASnapshot_StayOutOfHotspots() + { + var trace = new TraceScript() + .Begin(1, 0) + .Span(2, 1_000, 2_000) + .ToSession(end: 5_000, isSnapshot: true) + .Process(); + + Assert.AreEqual(2, trace.HotspotsByInclusiveDesc.Single().Id); + Assert.AreEqual(5.0, trace.GlobalRoot.Children.Single().InclusiveMs); + } + private static TraceScript Script() { return new TraceScript() diff --git a/tests/EmberTrace.Tests/ReportText/CollapsedStackTests.cs b/tests/EmberTrace.Tests/ReportText/CollapsedStackTests.cs index edc1198..37bd116 100644 --- a/tests/EmberTrace.Tests/ReportText/CollapsedStackTests.cs +++ b/tests/EmberTrace.Tests/ReportText/CollapsedStackTests.cs @@ -1,3 +1,5 @@ +using EmberTrace.Sessions; + namespace EmberTrace.Tests.ReportText; [TestClass] @@ -54,10 +56,54 @@ public void NullArguments_Throw() Assert.ThrowsExactly(() => TraceText.WriteCollapsedStacks(trace, null!)); } + [TestMethod] + public void OpenScopesInASnapshot_AreWeighedUpToTheCut() + { + var session = new TraceScript().Begin(1, 0).Span(2, 1_000, 2_000).ToSession(end: 5_000, isSnapshot: true); + + Assert.AreEqual("Outer 4000\nOuter;Inner 1000\n", Collapse(session, (1, "Outer"), (2, "Inner"))); + } + + [TestMethod] + public void OpenAsyncScopesInASnapshot_CloseInnermostFirst() + { + var session = new TraceScript() + .AsyncBegin(1, 0, 10) + .AsyncBegin(2, 1_000, 11, 10) + .ToSession(end: 5_000, isSnapshot: true); + + Assert.AreEqual("Request 1000\nRequest;Db 4000\n", Collapse(session, (1, "Request"), (2, "Db"))); + } + + [TestMethod] + public void OpenScopesInAStoppedSession_AreLeftOut() + { + var session = new TraceScript().Begin(1, 0).Span(2, 1_000, 2_000).ToSession(end: 5_000); + + Assert.AreEqual("Outer;Inner 1000\n", Collapse(session, (1, "Outer"), (2, "Inner"))); + } + + [TestMethod] + public void ConcurrentAsyncChildren_AreEachWeighedByTheirOwnTime() + { + var script = new TraceScript() + .AsyncBegin(1, 0, 10) + .AsyncBegin(2, 0, 11, 10).AsyncEnd(2, 4_000, 11, 10) + .AsyncBegin(3, 0, 12, 10).AsyncEnd(3, 3_000, 12, 10) + .AsyncEnd(1, 4_000, 10); + + Assert.AreEqual("Fan;A 4000\nFan;B 3000\n", Collapse(script, (1, "Fan"), (2, "A"), (3, "B"))); + } + private static string Collapse(TraceScript script, params (int Id, string Name)[] names) + { + return Collapse(script.ToSession(), names); + } + + private static string Collapse(TraceSession session, params (int Id, string Name)[] names) { using var writer = new StringWriter(); - TraceText.WriteCollapsedStacks(script.ToSession().Process(), writer, + TraceText.WriteCollapsedStacks(session.Process(), writer, Meta.Of(names.Select(n => (n.Id, n.Name, (string?)null)).ToArray())); return writer.ToString(); } diff --git a/tests/EmberTrace.Tests/Sessions/SessionClockTests.cs b/tests/EmberTrace.Tests/Sessions/SessionClockTests.cs index 10b66af..2fd47f4 100644 --- a/tests/EmberTrace.Tests/Sessions/SessionClockTests.cs +++ b/tests/EmberTrace.Tests/Sessions/SessionClockTests.cs @@ -1,11 +1,14 @@ using System.Diagnostics; using EmberTrace.Sessions; +using EmberTrace.Tracing; namespace EmberTrace.Tests.Sessions; [TestClass] public class SessionClockTests { + private static readonly DateTimeOffset Noon = new(2026, 9, 30, 12, 0, 0, TimeSpan.Zero); + [TestMethod] public void Stop_RecordsWhenTheSessionStarted() { @@ -21,35 +24,33 @@ public void Stop_RecordsWhenTheSessionStarted() } [TestMethod] - public void FullSnapshot_SharesTheSessionAnchor() + [DataRow(0)] + [DataRow(50)] + public void Snapshot_IsAnchoredToTheWallClockAtItsCut(int windowMs) { - using var tracing = new TracingSession(); - tracing.Start(new SessionOptions { ChunkCapacity = 1024 }); - tracing.Instant(1); + var clock = new ManualTimeProvider(Noon); + var profiler = new Profiler(clock); + profiler.Start(new SessionOptions { ChunkCapacity = 1024 }); + profiler.Instant(1); + Thread.Sleep(100); + clock.Now += TimeSpan.FromMinutes(3); - var snapshot = tracing.Snapshot(); - var stopped = tracing.Stop(); + var snapshot = profiler.Snapshot(TimeSpan.FromMilliseconds(windowMs)); + profiler.Stop(); - Assert.AreEqual(stopped.StartTimestamp, snapshot.StartTimestamp); - Assert.AreEqual(stopped.StartedAtUtc, snapshot.StartedAtUtc); + Assert.AreEqual(clock.Now, + snapshot.StartedAtUtc!.Value + Stopwatch.GetElapsedTime(snapshot.StartTimestamp, snapshot.EndTimestamp)); } [TestMethod] - public void WindowedSnapshot_ShiftsTheAnchorToItsFirstTimestamp() + public void Stop_KeepsTheAnchorTakenAtStart() { - using var tracing = new TracingSession(); - tracing.Start(new SessionOptions { ChunkCapacity = 1024 }); - Thread.Sleep(250); - tracing.Instant(1); + var clock = new ManualTimeProvider(Noon); + var profiler = new Profiler(clock); + profiler.Start(new SessionOptions { ChunkCapacity = 1024 }); + clock.Now += TimeSpan.FromMinutes(3); - var snapshot = tracing.Snapshot(TimeSpan.FromMilliseconds(50)); - var stopped = tracing.Stop(); - - var expected = stopped.StartedAtUtc!.Value - + Stopwatch.GetElapsedTime(stopped.StartTimestamp, snapshot.StartTimestamp); - - Assert.IsGreaterThan(stopped.StartTimestamp, snapshot.StartTimestamp); - Assert.AreEqual(expected, snapshot.StartedAtUtc); + Assert.AreEqual(Noon, profiler.Stop().StartedAtUtc); } [TestMethod] @@ -57,4 +58,10 @@ public void FromEvents_HasNoAnchor() { Assert.IsNull(TraceSession.FromEvents([], 0, 0, 1_000_000).StartedAtUtc); } + + [TestMethod] + public void FromEvents_KeepsTheGivenAnchor() + { + Assert.AreEqual(Noon, TraceSession.FromEvents([], 0, 0, 1_000_000, startedAtUtc: Noon).StartedAtUtc); + } } diff --git a/tests/EmberTrace.Tests/TestSupport/ManualTimeProvider.cs b/tests/EmberTrace.Tests/TestSupport/ManualTimeProvider.cs new file mode 100644 index 0000000..2ace9dc --- /dev/null +++ b/tests/EmberTrace.Tests/TestSupport/ManualTimeProvider.cs @@ -0,0 +1,11 @@ +namespace EmberTrace.Tests; + +internal sealed class ManualTimeProvider(DateTimeOffset now) : TimeProvider +{ + public DateTimeOffset Now { get; set; } = now; + + public override DateTimeOffset GetUtcNow() + { + return Now; + } +} diff --git a/tests/EmberTrace.Tests/TestSupport/TraceScript.cs b/tests/EmberTrace.Tests/TestSupport/TraceScript.cs index 0cdf4ab..391eb6f 100644 --- a/tests/EmberTrace.Tests/TestSupport/TraceScript.cs +++ b/tests/EmberTrace.Tests/TestSupport/TraceScript.cs @@ -38,15 +38,27 @@ public TraceScript Flow(TraceEventKind kind, int id, long timestamp, long flowId return Add(id, thread, timestamp, kind, flowId, 0); } + public TraceScript AsyncBegin(int id, long timestamp, long scopeId, long parentScopeId = 0, int thread = 1) + { + return Add(id, thread, timestamp, TraceEventKind.Begin, scopeId, parentScopeId); + } + + public TraceScript AsyncEnd(int id, long timestamp, long scopeId, long parentScopeId = 0, int thread = 1) + { + return Add(id, thread, timestamp, TraceEventKind.End, scopeId, parentScopeId); + } + public TraceSession ToSession( long start = 0, long? end = null, ITraceMetadataProvider? metadata = null, - IReadOnlyDictionary? threadNames = null) + IReadOnlyDictionary? threadNames = null, + bool isSnapshot = false) { var ordered = _events.OrderBy(e => e.Timestamp).ThenBy(e => e.ThreadId).ThenBy(e => e.Sequence).ToList(); var last = ordered.Count == 0 ? start : ordered[^1].Timestamp; - return TraceSession.FromEvents(ordered, start, end ?? last, frequency, threadNames, metadata); + return TraceSession.FromEvents(ordered, start, end ?? last, frequency, threadNames, metadata, + isSnapshot: isSnapshot); } private TraceScript Add(int id, int thread, long timestamp, TraceEventKind kind, long flowId, long value)