Operation logger

Question

GitHub, NuGet

This component traces execution in a logical order instead of chronological as everybody else :)

For example, the following code:

    static async Task MainAsync()
    {
        Op.Log.Subscribe(WriteLine);
        using (new Op())
            await Task.WhenAll(
                from i in Range(0, 4)
                select AlphaAsync());
    }

    private static async Task AlphaAsync()
    {
        using (new Op("Alpha function"))
            await BetaAsync();
    }

    private static async Task BetaAsync()
    {
        using (var op = new Op())
        {
            op.Trace("Waiting...");
            await Task.Delay(100);
            op.Trace("Continue");
        }
    }

Will generate:

MainAsync took 116 ms
  Alpha function took 109 ms
    BetaAsync took 108 ms
      Waiting... after 0 ms
      Continue after 108 ms
  Alpha function took 109 ms
    BetaAsync took 109 ms
      Waiting... after 0 ms
      Continue after 109 ms
  Alpha function took 109 ms
    BetaAsync took 109 ms
      Waiting... after 0 ms
      Continue after 109 ms
  Alpha function took 111 ms
    BetaAsync took 111 ms
      Waiting... after 0 ms   
      Continue after 111 ms

Which is a way more readable…

The Op class is defined as:

public class Op : IDisposable
{
    public static IObservable<string> Log => Subject;
    static Subject<string> Subject { get; } = new Subject<string>();
    static AsyncLocal<Op> Context { get; } = new AsyncLocal<Op>();

    public Op([CallerMemberName] string text = null)
    {
        Parent = Context.Value;
        Context.Value = this;
        Stopwatch = Stopwatch.StartNew();
        Indent = Parent == null ? "" : Parent.Indent + "  ";
        Frame = new List<(string, Func<string>)>();
        Frame.Add((Indent + text, () => $"took {Stopwatch.ElapsedMilliseconds} ms"));
    }

    Op Parent { get; }
    Stopwatch Stopwatch { get; }
    string Indent { get; }

    List<(string Text, Func<string> Time)> Frame { get; }

    public void Dispose()
    {
        Stopwatch.Stop();
        Context.Value = Parent;
        if(Parent != null)
            lock(Parent.Frame)
            lock(Frame)
                Parent.Frame.AddRange(Frame);
        else
            Subject.OnNext(ToString());
    }

    public void Trace(string text)
    {
        var ms = $"after {Stopwatch.ElapsedMilliseconds} ms";
        lock(Frame)
            Frame.Add((Indent + "  " + text, () => ms));
    }

    public override string ToString()
    {
        lock(Frame)
            return Join(NewLine,
                from row in Frame
                select $"{row.Text} {row.Time()}");
    }
}

Answer 1

One drawback I can think of this way of logging is that (correct me if I'm wrong) it is lazy. That's to say, until the root Op object is Disposed, all of the log items are kept in memory. This means that you are relying entirely on the functionality of the topmost using statement to ensure the log gets properly written somewhere. If due to some external error your process happens to exit unexpectedly, you might end up losing your entire log.

---

    if(Parent != null)
        lock(Parent.Frame)
        lock(Frame)
            Parent.Frame.AddRange(Frame);
    else
        Subject.OnNext(ToString());

No-one has died from using some {}-braces. Why not use them?