Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 5 additions & 0 deletions docs/guides/analysis/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
6 changes: 6 additions & 0 deletions docs/guides/analysis/README.ru.md
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
16 changes: 9 additions & 7 deletions docs/guides/hosting/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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}`;
Expand Down Expand Up @@ -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

Expand Down
17 changes: 10 additions & 7 deletions docs/guides/hosting/README.ru.md
Original file line number Diff line number Diff line change
Expand Up @@ -100,7 +100,7 @@ builder.Services.AddEmberTrace(builder.Configuration.GetSection("Tracing"));

## Что записывает middleware

Для каждого запроса, не попавшего в `IgnoredPaths`:
Для каждого запроса, не попавшего в `IgnoredPaths` и не адресованного `Path` эндпоинта дампа:

- асинхронный скоуп с именем `"{METHOD} {шаблон маршрута}"`, например `GET /orders/{id}`; количество
идентификаторов ограничено `MaxTrackedRoutes`, и после достижения лимита новые маршруты схлопываются
Expand Down Expand Up @@ -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` не открывает. Захваты выполняются в пуле потоков по одному: медленный запрос не замедляется ещё больше,
ошибка записи логируется и никогда не выбрасывается, а корректная остановка хоста дожидается захвата, который уже
идёт. Запись запросов должна оставаться включённой.

## Жизненный цикл сессии

Expand Down
6 changes: 4 additions & 2 deletions docs/reference/opentelemetry/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
6 changes: 4 additions & 2 deletions docs/reference/opentelemetry/README.ru.md
Original file line number Diff line number Diff line change
Expand Up @@ -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`; только сессии без него откатываются к «сейчас минус
длительность сессии».

## Примечания

Expand Down
11 changes: 7 additions & 4 deletions src/EmberTrace.Analysis/Analyzers/CallTreeBuilder.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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);
Expand All @@ -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)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -50,11 +50,11 @@ private static void ValidateSlowRequests(EmberTraceOptions options, List<string>
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.");
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -9,18 +9,21 @@ namespace EmberTrace.Extensions.Hosting;

internal sealed class EmberTraceHostedService : IHostedService
{
private readonly SlowRequestCapture _capture;
private readonly ILogger<EmberTraceHostedService> _logger;
private readonly EmberTraceOptions _options;
private readonly EmberTraceRecorder _recorder;

public EmberTraceHostedService(
EmberTraceRecorder recorder,
SlowRequestCapture capture,
IOptions<EmberTraceOptions> options,
ILogger<EmberTraceHostedService> 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));
}
Expand All @@ -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)
Expand Down
25 changes: 15 additions & 10 deletions src/EmberTrace.Extensions.Hosting/Http/EmberTraceMiddleware.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand All @@ -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);
}
}

Expand All @@ -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<SlowRequestCapture>()?.TryCapture(request, elapsed);
context.RequestServices?.GetService<SlowRequestCapture>()?.TryCapture(options, request, started, elapsed);
}

private static int ResolveId(HttpContext context, EmberTraceRequestOptions requests)
Expand All @@ -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];
Expand Down
74 changes: 51 additions & 23 deletions src/EmberTrace.Extensions.Hosting/Recording/SlowRequestCapture.cs
Original file line number Diff line number Diff line change
@@ -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<EmberTraceOptions> options,
ILogger<SlowRequestCapture> logger,
TimeProvider time)
internal sealed class SlowRequestCapture(ILogger<SlowRequestCapture> 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);
}

Check notice

Code scanning / CodeQL

Generic catch clause Note

Generic catch clause.
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;
}
}
Loading
Loading