DOCSEARCHbyAlgolia
Submit Docs

Serilog Timings

repository·dev·Indexed 42 days ago

https://github.com/nblumhardt/serilog-timings

A lightweight library for recording operation durations as structured log events in Serilog. It provides consistent properties like Elapsed and Outcome, offering simple timing via Operation.Time() and advanced control through Operation.Begin(), including support for custom log levels and OperationId tracing via LogContext.

Tokens
1.2K
Snippets
5
Records
7
Agent score
3%

What's inside Serilog Timings

  1. Enable `OperationId` tracing with `LogContext`

    dev

    To make it easier to trace timing results back to the specific operation that raised them, enable Serilog's LogContext feature in your LoggerConfiguration using .Enrich.FromLogContext().

    When enabled, Serilog Timings automatically adds an OperationId property to all log events generated within a timing block.

  2. Advanced operation control with `Operation.Begin()`

    dev

    For operations that can succeed, fail, or produce specific results, use Operation.Begin(). This provides manual control over the operation's outcome.

    Outcomes:

    • Success: Call op.Complete(). This logs an Information level event with Outcome = "completed".
    • Failure/Abandonment: If the block exits without calling Complete(), a Warning level event is logged with Outcome = "abandoned".
    • Cancellation: Call op.Cancel() to suppress all logging for that operation (no event is written for completion or abandonment).

    Adding extra properties: You can attach additional data to the log event using op.Complete(propertyName, value). This does not change the log message text but adds the property for filtering.

    using SerilogTimings;

using (var op = Operation.Begin("Retrieving orders for {CustomerId}", customer.Id))
{
    // Timed block of code goes here

    op.Complete("Rows", orders.Rows.Length);
}
// Log output: [INF] Retrieving orders for customer-67890 completed in 7.8 ms (with property Rows attached)

  4. Important caveat: Argument capture timing

    dev

    Because Serilog Timings does not write the log event until the using block completes (or Complete() is called), the arguments passed to Begin() or Time() are not captured until that moment.

    Warning: Do not pass parameters to these methods that might mutate during the operation, as the value recorded will be the state of the object at the time the operation finishes, not when it starts.

  5. Basic timing of an operation with `Operation.Time()`

    dev

    The simplest way to time a block of code is using Operation.Time(). This method accepts a message template. When the using block completes, a single log event is emitted.

    Key behaviors:

    • The log message is automatically extended with " {Outcome} in {Elapsed} ms".
    • All events carry an Elapsed property (in milliseconds).
    • For Time(), the Outcome property is always "completed".
    • All properties from the template are recorded as first-class properties on the log event.
    using SerilogTimings;

using (Operation.Time("Submitting payment for {OrderId}", order.Id))
{
    // Timed block of code goes here
}
// Log output: [INF] Submitting payment for order-12345 completed in 456.7 ms

  6. Use timing extensions with `ILogger`

    dev

    If you have an existing ILogger instance, you can use extension methods to route timings through that specific logger context.

    • logger.TimeOperation(template, args...): Equivalent to Operation.Time().
    • logger.BeginOperation(template, args...): Equivalent to Operation.Begin().
    • logger.OperationAt(level).Time(template, args...): Allows you to specify a custom LogEventLevel for the timing events.
    // Using TimeOperation
using (logger.TimeOperation("Submitting payment for {OrderId}", order.Id))
{
    // ...
}

// Using OperationAt to set a specific level
using (requestLogger.OperationAt(LogEventLevel.Debug).Time("Fetching"))
{
    // ...
}

  7. Configure timing log levels with `Operation.At()`

    dev

    By default, timings are recorded at the Information level. To record timings at Debug or Verbose levels, use Operation.At() or the OperationAt() extension method.

    Operation.At(level, abandonmentLevel) allows you to specify different levels for completion and abandonment events.

    // All events (completion and abandonment) will be Debug level
using (Operation.At(LogEventLevel.Debug).Time("Preparing zip archive"))
{
    // ...
}