Added ability to log timings as Warnings for operations that take longer than expected

[pawelpabich]

Stole the idea from @uglybugger :). This extension helps easily identify code paths that are slower than expected.

[nblumhardt]

Thanks Pawel!

I'm not sure exactly how this should integrate with _abandonmentLevel - if users set the abandonment level to Error, then it would seem unexpected for a "slow" error to downgrade this to Warning 🤔

Some earlier discussion on this feature - https://github.com/nblumhardt/serilog-timings/issues/17#issuecomment-281845799 - guessing that in your case though, you're more interested in suppressing an event in the non-Warning case?

[pawelpabich]

I'm not sure exactly how this should integrate with _abandonmentLevel - if users set the abandonment level to Error, then it would seem unexpected for a "slow" error to downgrade this to Warning

Thanks for the review!

The condition has two parts and the second part is responsible for makings sure the downgrade doesn't happen. I added a test that shows that.

level = elapsed > _warningThreshold?.TotalMilliseconds && level < LogEventLevel.Warning

[pawelpabich]

Some earlier discussion on this feature - https://github.com/nblumhardt/serilog-timings/issues/17#issuecomment-281845799 - guessing that in your case though, you're more interested in suppressing an event in the non-Warning case?

I'm happy to log in both cases. I need long-running operations to stand out. Also, having the same message format for both the Warning and the non-Warning case would be a plus.

Happy to close the PR if you believe this feature doesn't fit nicely into the overall design of the library.

[nblumhardt]

Thanks for the follow-up, sorry about the slow reply! Have been enjoying a week at the beach :-)

I think I'm on board with the functionality :+1:

API-wise, although there would seem to be some more juggling of parameters internally, I think LevelledOperation is the better place to configure the warning threshold.

For example, in the PR branch I think this test would fail:

        [Fact]
        public async Task LongOperationsAreLoggedAsWarnings()
        {
            var operationDuration = TimeSpan.FromMilliseconds(100);

            var logger = new CollectingLogger();
            var op = logger.Logger
                .OperationAt(LogEventLevel.Debug)  // Debug is off by default...
                .Begin("Test")
                .WithWarningThreshold(operationDuration); // ... seems like this should be emitted?

            await Task.Delay(operationDuration + operationDuration);

            op.Complete();

            Assert.Equal(LogEventLevel.Warning, logger.Events.Single().Level);
        }

Not sure it's the best way to expose it, but:

            var op = logger.Logger
                .OperationAt(LogEventLevel.Debug, warningThreshold: operationDuration)
                .Begin("Test")

might appear to work more predictably?

[pawelpabich]

Thanks for the follow-up, sorry about the slow reply! Have been enjoying a week at the beach :-)

I know how it feels I just returned from a similar trip :)

For example, in the PR branch I think this test would fail:

The test seems to pass for me but I agree that moving the warning configuration to OperationAt results in a better API. I will put together a PR soon.

[nblumhardt]

Ah, I see - sorry. CollectingLogger sets the minimum level to Verbose: https://github.com/nblumhardt/serilog-timings/blob/dev/test/SerilogTimings.Tests/Support/CollectingLogger.cs#L17 (my assumption was that it used Information, which would cause the test to make sense/fail).

[pawelpabich]

Superseded by https://github.com/nblumhardt/serilog-timings/pull/43