Customizable level timing

[matt-softlogic]

@nblumhardt while I agree it's good that this framework have an opinion about logging levels for timed operations, as you stated in the Readme, in some situations, like the project I'm working on, we're looking for timing in the logs for things we wouldn't necessarily want on in Production.

I would like to suggest you make an optional overload for the Operation to control logging level, that way Information is still the default, but we can control it in a way that makes sense in our situation.

Thanks, and nice job!

[nblumhardt]

Hey Matt! Thanks for the note. I set out to keep the API small and focused on the core monitoring scenario, but I'm open to squeezing something in if the impact is low enough. Here's one possible proposal to consider:

I don't want to overload Time() or Begin() because the signatures would be a bit unwieldy, but what do you think of:

using (Operation.At(LogEventLevel.Debug).Time("Hello"))
{
    // ...

A bit harsher on the eyes, but not too bad, and Operation only grows by one method that will sit somewhat out of the way.

It's not AtDebug() etc. because the very next feature request will be to also control (separately) the abandonment event's level:

using (Operation.At(LogEventLevel.Debug, LogEventLevel.Error).Begin("Hello"))
{
    // ...

If this is the way forward, would the first version of the method (where the abandonment level is not specified) default it to Warning, or to whatever was specified for the completion event? I think doing the latter - so setting both to Debug could be more useful in practice though it's a bit less intuitive.

Finally, to properly cover the off-in-production scenario, At() would need to check the current logging level up-front, and return a cached, canceled (and thus thread-safe/immutable) operation instance so that the cost of creating the Stopwatch and so-on is avoided.

What do you think? Would the library still be compelling with the second-class debug-time API?

[matt-softlogic]

Hey Nicholas, thanks for the quick and well thought out reply! Our team is new to Serilog and Seq and we Love your work!

Just speaking purely from a code readability POV, I prefer to see the operation name come before the level, so if it's possible, would you consider this approach:

using (Operation.Time("Hello").At(LogEventLevel.Debug))
{
    // ... 

As for the abandonment level, to be perfectly honest, we haven't started using that, but I could see defaulting to the completion level, with the option to elevate as a nice to have.

That probably throws a spanner into the last Finally part of the conversation, but something for you to think about...

Thanks again, and keep up the good work!

--matt

[nblumhardt]

Thanks!

Yeah, that's the challenge - I think the amount of allocation/work done by Begin() could become a problem if used that way in the debug/verbose scenario.

There's also a bit of rightward drift possible that might obscure the level:

using (Operation.Time("Hello hello hello {Hello} hello {Hello}", hello1, hello2).At(LogEventLevel.Debug))
{
    // ... 

Guessing you wouldn't call level-on-the-left a showstopper then? :-)

[matt-softlogic]

Not a showstopper, just a nice to have.

thanks.

[nblumhardt]

Done; thanks for the feedback Matt. Should be through CI soon. :-)