.NET Standard 2.1: Logging, tracing and profiling

UI development requires asynchronous operations to implement snappy behavior. Sometimes debug is not the best option. For my Blazor app, I wanted to trace some of method calls if needed. Searching internet didn’t reveal any existing lightweight solution. So, I came up with a simple log scoping solution based on IDisposable. In the shared assembly of my existing project NoCrast, I added Logging namespace. Initial solution should support logging to the system console but be extensible to support any other logging solutions like log4net, NLog, etc. To keep things simple, ILog interface has been introduced inherited from IDiposable. ILog represents a log scope that should log scope's beginning and the end. Logging of the "end" event is taken care by Dispose method. Logging of the scope's begin is done during instantiation. Thus, we also need a provider that will provide instance of the log:

public interface ILogProvider
{
    ILog CreateLogger(string scope);
}

Also, it would be useful to create nested scopes. ILog.CreateScope has been introduced for this purpose:

public interface ILog : IDisposable
{
    ILog CreateScope(LogLevel level, string scope);
}

So, you can create a nested scope from existing one if you need to profile specific section of a method. Also, I implemented several extension methods to help with some common tasks:

public static class LoggingExtensions
{
    public static ILog CreateLogger(this ILogProvider provider, Object scope)
    {
        return provider.CreateLogger(scope.GetType().Name);
    }

    public static void D(this ILog log, string message)
    {
        log.Line(LogLevel.DEBUG, message);
    }
    public static ILog DebugScope(this ILog log, [CallerMemberName] string scope = "scope")
    {
        return log.CreateScope(LogLevel.DEBUG, scope);
    }
    ...
}

To understand how it works, let’s look into the following example:

class MyClass
{
    ILog classScope;

    public MyClass(ILogProvider provider)
    {
        classScope = provider.CreateLogger(this);
    }

    public void MethodA()
    {
        using (var methodScope = classScope.DebugScope())
        {
            methodScope.D("Inside of method A scope");
            Thread.Sleep(200);
            using (var aScope = methodScope.DebugScope("a-scope"))
            {
                aScope.D("Inside of a scope");
            }
            MethodB();
        }
    }

    private void MethodB()
    {
        using (var methodScope = classScope.DebugScope())
        {
            methodScope.D("Inside of method B scope");
            Thread.Sleep(200);
        }
    }
}

Let’s assume we instantiate MyClass with reference to ILogProvider that implements log to the system console and call MethodA. If you look at the example above, MethodA create a method wide scope by DebugScope. That scope calls DebugScope again to create nested scope “a-scope”. MethodA calls private MethodB that creates it’s own scope. So log will look like this:

--> begin of MyClass:MethodA
    MyClass:MethodA: Inside of method A scope
--> begin of MyClass:MethodA:a-scope
    MyClass:MethodA:a-scope: Inside of a scope
<-- end of MyClass:MethodA:a-scope, time:3 msec
--> begin of MyClass:MethodB
    MyClass:MethodB: Inside of method B scope
<-- end of MyClass:MethodB, time:202 msec
<-- end of MyClass:MethodA, time:425 msec

Please note that “a-scope” has full name MyClass:MethodA:a-scope because it is a nested scope of the MethodA. This solution helps provide detailed logging and profiling of method or specific area without polluting code too much with logging calls.

Please look at NoCrast project logging for the implementation details.