Feature Request: Warn if exceeds

[davidpeden3]

I started porting all of my timing code away from SerilogMetrics and ran into one case that I find quite useful. The other library had a notion of wrapping a block of code and logging a warning if it exceeded a certain time threshold. It would be great to have this feature.

Alternatively, I looked for an .ElapsedTime property on the Operation class but didn't see one. Would be nice to have that hydrated upon calling .Complete().

[nblumhardt]

What would you think of having Complete() return a TimeSpan? This seems like it would make it easy to generate a warning appropriately (just a slight variation on your .ElapsedTime suggestion).

[davidpeden3]

Returning a TimeSpan from .Complete() would be ok but why not just create a delegating property to the underlying _stopwatch.Elapsed? Wouldn't that be cleaner and simpler? It would also allow for a check of the elapsed time at any point during the operation and not just the completion. It would also still be useful in the case that .Cancel() was called.

[nblumhardt]

Thanks for the follow-up! I think under this scheme Cancel() would just return the elapsed time also. But, I can see the merits of the property-based approach as well.

The return value might be a bit leaner to implement once we've removed the Stopwatch ( #18 ), since we'd only need to store a long with the Operation, rather than a pair of long start/stop values so that Elapsed could be computed later. It's not a big deal, but this library is one where I'm letting my design OCD have free reign for now (so that I don't drive everyone mad with it on the other projects ;-))

[davidpeden3]

This is the code example from #17:

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

The extraneous Stopwatch would not be required to accomplish this code flow if .ElapsedTime were to be exposed. And with return values, this code flow is not even possible without it.

The perf gain of only storing a single long vs two doesn't seem worth the compromise in capability if the API exposes a property vs. return values.

In your example (also from #17):

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

I'm personally not a fan of calling .Complete() inside of the if. That's a really important bit of code that gets lost in the noise, IMO.

Ultimately, it boils down to fundamental design preference and coding style. Though it seems we differ in opinion, a return value is better than nothing at all. ;)

[nblumhardt]

You're probably right about the overhead of an extra long.

The if block could still be better written:

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

I'm coming around on the Elapsed property. Are you (or is anyone following along) interested in PRing it up?

Thanks for all the input @davidpeden3!

[davidpeden3]

I'll send in a PR. But first I need to fix my environment. I've been living in the world of nightly builds with a few PRs to MS and was unable to compile your solution as is. May be a few days.

[pardahlman]

Hello 👋 - I think that we try to achieve the same thing in #14 as #17. I'm glad that we are exploring different options 👍

The thing I don't like with this approach is that we would still get two log entries from the operation, as Complete will perform a Write. It will create a lot of unnecessary entries when debug logging is activated.

Also, if we're just looking to find a way to write entries with different log levels and same message, the Log.Warning("...") would need to use the same string or duplicate the string from where the operation was created.

Lastly, as @nblumhardt pointed out to in #17, the logic for removing properties from LogContext would need to be updated if the Log.Warning("...") would have a reference to theOperationId` (which I really think it should).

Sorry if I sound grumpy, it is not my intention! At the moment, I would very much like a solution where the logic for this can be declared when creating the Operation, and that the user would just need to Complete the operation and get appropriate log level.

Cheers!

[benfoster]

Hi,

Just to chime in on this issue, we are looking for something similar as we’re finding that logging each and every operation in our system is becoming a bottleneck.

What I want to achieve is a different log level based on a specified threshold (Timespan). Passing this in complete makes sense to me but most of our code uses the terser Logger.TimeOperation syntax.

I’d imagine due to the log entry params, changing this method to support the threshold (or indeed a delegate) would be a breaking change so how about something like TimeOperationWhen?

We could have some sugar around the delegate for common behaviour such as setting log level based on the time.