Use logf to make logging more typesafe

[jwosty]

Converts usages of ILogger.Log* to logf and friends from https://github.com/jwosty/FSharp.Logf.

This converts many but not all calls -- there are still plenty left. If you like this contribution, I am happy to add more commits to finish the rest.

[Lanayx]

Hi! Thank you for the PR! Please note, that this is a high-performance library, so your PR can be accepted only if you library doesn't add any performance overhead over ILogger usage. Do you have any performance benchmarks of your library? I suspect that all %A usage can be quite expensive. Another thing is ergonomics - changing Log.Logger.LogInformation to logfi Log.Logger doesn't add much, but if you could use partial application on the Log.Logger level like let logfi = logfi Log.Logger and use just logfi everywhere, this would improve things from readability perspective, however performance of this solution should be checked as well

[jwosty]

@Lanayx, thanks for the feedback. I've assembled some benchmarks (sources are here). TL;DR: logf adds significant overhead to naked ILogger calls for a NullLogger, however this overhead is completely dwarfed when you plug in a logger with real I/O (like the Serilog JSON file logger) by the logger's own overhead (presumably because of the parsing of the format string it itself does) - in which case, it is only about 2x as slow.

This is the true regardless of the formatting specifier used (re: your concerns about %A), because FSharp.Logf has a dirty secret: the formatters just pass the object through to the underlying ILogger.

If a 2x slowdown on each logging call (even for calls with 10 parameters which is quite a lot!) is too much for this library, I'd be happy to investigate some perf improvements (as it stands, I haven't done this yet). These two bottlenecks are what I suspect to be optimization candidates:

1. F# printf string parsing (which I can't do anything about, but which also impacts all F# printf calls)
2. This Regex. Rewriting it with some manual parsing code could potentially give some nice boosts.

Here are (some of) the benchmarks for reference:

BenchmarkDotNet=v0.13.3, OS=macOS Monterey 12.6 (21G115) [Darwin 21.6.0]
Apple M1 Pro, 1 CPU, 10 logical and 10 physical cores
.NET SDK=6.0.302
  [Host]   : .NET 6.0.12 (6.0.1222.56807), Arm64 RyuJIT AdvSIMD DEBUG
  .NET 6.0 : .NET 6.0.12 (6.0.1222.56807), Arm64 RyuJIT AdvSIMD

Job=.NET 6.0  Runtime=.NET 6.0  InvocationCount=1  
UnrollFactor=1  

Method	size	provider	Mean	Error	StdDev	Median	Ratio	RatioSD
NoParams	100000	NullLogger	1,117.50 μs	17.909 μs	16.752 μs	1,114.25 μs	1.00	0.00
LogfNoParams	100000	NullLogger	141,037.53 μs	170.991 μs	151.579 μs	140,986.42 μs	126.17	1.87
OneParam	100000	NullLogger	8,520.59 μs	97.667 μs	91.358 μs	8,540.60 μs	7.63	0.13
LogfOneParam	100000	NullLogger	207,968.82 μs	453.589 μs	402.095 μs	207,879.44 μs	186.05	2.83
TwoParams	100000	NullLogger	9,022.34 μs	95.008 μs	88.870 μs	8,993.83 μs	8.08	0.15
LogfTwoParams	100000	NullLogger	246,559.28 μs	670.201 μs	594.116 μs	246,632.81 μs	220.57	3.16
TenParams	100000	NullLogger	8,996.33 μs	80.538 μs	71.395 μs	8,998.54 μs	8.05	0.15
LogfTenParams	100000	NullLogger	248,528.74 μs	376.392 μs	333.661 μs	248,605.92 μs	222.33	3.53
LogfTenParamsPercentA	100000	NullLogger	247,647.43 μs	311.212 μs	291.108 μs	247,716.62 μs	221.66	3.41
NoParams	100000	SerilogFileLogger	287,239.03 μs	846.633 μs	706.977 μs	287,175.21 μs	1.00	0.00
LogfNoParams	100000	SerilogFileLogger	460,612.08 μs	1,621.929 μs	1,354.384 μs	460,968.88 μs	1.60	0.01
OneParam	100000	SerilogFileLogger	330,668.93 μs	1,007.196 μs	841.054 μs	330,571.75 μs	1.15	0.00
LogfOneParam	100000	SerilogFileLogger	599,113.13 μs	2,474.888 μs	2,066.644 μs	598,748.42 μs	2.09	0.01
TwoParams	100000	SerilogFileLogger	358,458.56 μs	1,793.355 μs	1,497.533 μs	358,022.62 μs	1.25	0.01
LogfTwoParams	100000	SerilogFileLogger	670,566.34 μs	3,925.497 μs	3,277.968 μs	670,653.79 μs	2.33	0.01
TenParams	100000	SerilogFileLogger	358,236.93 μs	1,307.517 μs	1,091.836 μs	358,599.29 μs	1.25	0.00
LogfTenParams	100000	SerilogFileLogger	650,437.64 μs	1,927.200 μs	1,504.631 μs	650,587.13 μs	2.26	0.01
LogfTenParamsPercentA	100000	SerilogFileLogger	653,951.45 μs	4,064.348 μs	3,393.915 μs	655,406.71 μs	2.28	0.02

[jwosty]

Additionally, I'd be happy to curry logf calls in the way you described in this PR if this is the kind of thing you'd accept.

[Lanayx]

Hi, I've done my own testing with this code (with particular cases relevant for this repository):

[<MemoryDiagnoser>]
[<SimpleJob(RuntimeMoniker.Net60)>]
type Benchmarks() =

    let factory = new Serilog.Extensions.Logging.SerilogLoggerFactory(LoggerConfiguration()
        .MinimumLevel.Information()
        .WriteTo.Console()
        .CreateLogger())
    let logger: ILogger = factory.CreateLogger()

    let logfiCurried template paramss = logfi logger template paramss
    let logfdCurried template paramss = logfd logger template paramss

    [<Benchmark>]
    member this.DebugConsoleRegular() =
        logger.LogInformation("Hello, {Name}!", "World")

    [<Benchmark>]
    member this.DebugConsoleLogF() =
        logfi logger "Hello, %A{Name}!" "World"

    [<Benchmark>]
    member this.DebugConsoleLogFCurried() =
        logfiCurried "Hello, %A{Name}!" "World"

    [<Benchmark>]
    member this.DebugNoneRegular() =
        logger.LogDebug("Hello, {Name}!", "World")

    [<Benchmark>]
    member this.DebugNoneLogF() =
        logfd logger "Hello, %A{Name}!" "World"

    [<Benchmark>]
    member this.DebugNoneLogFCurried() =
        logfdCurried "Hello, %A{Name}!" "World"

BenchmarkRunner.Run<Benchmarks>() |> ignore

And here are the results:

|                  Method |          Mean |        Error |       StdDev |   Gen0 | Allocated |
|------------------------ |--------------:|-------------:|-------------:|-------:|----------:|
|     DebugConsoleRegular | 214,148.53 ns | 4,127.826 ns | 7,229.555 ns |      - |    1456 B |
|        DebugConsoleLogF | 216,941.78 ns | 3,651.877 ns | 4,347.299 ns | 1.4648 |    5217 B |
| DebugConsoleLogFCurried | 212,830.97 ns | 4,063.342 ns | 8,481.707 ns | 1.4648 |    5297 B |
|        DebugNoneRegular |      70.78 ns |     1.332 ns |     1.246 ns | 0.0101 |      32 B |
|           DebugNoneLogF |   3,399.40 ns |    46.651 ns |    58.998 ns | 1.2054 |    3793 B |
|    DebugNoneLogFCurried |   4,075.95 ns |    75.898 ns |    74.542 ns | 1.2283 |    3873 B |

It appears that your library is bringing a giant overhead for debug case (when min level is set to info), also currying for readability adds even more overhead. Also I've made a though about the additional typing gain your library brings and it appeared that with %A cases doesn't bring any value at all, it's only useful for %i and %s cases. With that all in mind I'm closing the PR as not accepted, sorry for that