LogLevel for Timed Operations

[pardahlman]

Great work with this extension, I really like the clean API 👍

In our applications, we have a lot of operations that we want to time - one request can generate up to 20 operations that we want to measure. In order to make our logs more readable, we've used Serilog-Metrics timed operations and changed the log level based on a threshold value

using (_logger.BeginTimedOperation(
    description: EnrichOperation,
    identifier: enricher.GetType().Name,
    level: LogEventLevel.Debug,
    warnIfExceeds: TimeSpan.FromMilliseconds(100),
    levelExceeds: LogEventLevel.Information))
{
    // code goes here
}

This feature makes sense, as the outcome of a timed operation can have different "severity" based on the elapsed time.

Here's to my question: Do you have any suggestions how I might be able to use Serilog Timings to change the log level based on a timed operation's outcome? For our project, it would also be fine if the log was dismissed if the timed operation completed under the threshold value. This is what I've come up with so far

var op = Operation.At(LogEventLevel.Debug).Begin("...");
var sw = Stopwatch.StartNew();
// code here
sw.Stop();
if (sw.Elapsed > threshold)
{
    op.Cancel();
}
else
{
    op.Complete();
}

What I'm looking for is something less verbose.

As a side not, and really I'm just thinking out loud after spending a few minutes in your code base, I would want to be able to do something like this

using (Operation.At((outcome, elapsed) => LogEventLevel.Debug).Time("..."))
{
    // code goes here           
}

Not really sure of the type of outcome but perhaps something that indicate if the operation was abandoned or completed.

Cheers!

[pardahlman]

perhaps it makes more sense to have the func on timed operations only, as I guess that normal operations does not have a timer running. anyways, looking forward hearing your thought

[nblumhardt]

Thanks for kicking off the discussion. I would shy away from Func because it requires allocations that we should be able to avoid otherwise.

There's another ticket #14 that could come close; it'd be something like:

using (var op = Operation.At(LogEventLevel.Debug).Begin("..."))
{
    // Do things, then...

    if (op.Complete() > TimeSpan.FromSeconds(3))
    {
         Log.Warning("...");
    }
}

It's a little less "built-in" than the SerilogMetrics version, but it keeps the API simple.

The only caveat would be the propagation of OperationId: if Complete() pops it off of LogContext, the warning would end up needing to be:

         Log.Warning("Operation {OperationId} took...", op.OperationId, ...);

Or, we'd need to make sure the value is still pushed until Dispose() is called on op, which is less error-prone, but could be surprising given Complete() suggests the end of the operation.

What do you think?

[pardahlman]

I agree with your comment re the Func suggestions... I was tempted to find a solution that approached the log level problem from a different angel - that is instead of one threshold and two log levels, we would have an elapsed time and a code block that could return any log level. But - point taken!

Give me some time to get familiar with the lib, and I'll get back to you on you suggestion. Intuitively it feels like Complete() should end the entire operation. Taking a quick look in the code base it surprised me that Complete() doesn't dispose the operation, whereas Cancel() (with a similar signature) does. Also, based on my naive understanding, would not op.Complete() write a debug log in your example?

[nblumhardt]

Thanks for the follow-up. Yes, the complete/cancel semantics are a bit subtle.

The Complete() call in the example would write a entry; the code would probably be better presented as:

using (var op = Operation.At(LogEventLevel.Debug).Begin("..."))
{
    // Do things, then...

    var elapsed = op.Complete();
    if (elapsed > TimeSpan.FromSeconds(3))
    {
         Log.Warning("...");
    }
}

The specifics of obtaining the elapsed time are still being discussed in #14, it may end up shaped differently 👍

[nblumhardt]

I will close this one as stale, but if anyone's keen to pick it back up just let me know. Thanks!