8
\$\begingroup\$

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()}");
    }
}
\$\endgroup\$
  • 1
    \$\begingroup\$ I nominate this as question of the day I need some time to study AsyncLocal :p \$\endgroup\$ – dfhwze Sep 18 at 6:43
  • 1
    \$\begingroup\$ Some impressive code you posted, the only issue I would have for this in logging is the scope captured in the async state machine in production code as well as the rather large usage of the ThreadPool. I'm afraid that when using this in production code that your production code will get delayed. We had to remove quite a lot of Async code as we noticed delays of up-to several seconds on a 4x 32 Core server. One other thing, you should consider ConfigureAwait(false) not having it actually is considered an anti-pattern \$\endgroup\$ – PPann Sep 18 at 7:11
  • 1
    \$\begingroup\$ @dfhwze asynclocal is awesome. I use it a couple of projects and it is a great help. Actually I use the same way as Dmitry :-) \$\endgroup\$ – t3chb0t Sep 18 at 8:59
  • 1
    \$\begingroup\$ github.com/he-dev/reusable/blob/dev/Reusable.OmniLog/src/… @dfhwze this is the helper that encapsulates that logic \$\endgroup\$ – t3chb0t Sep 18 at 9:09
  • 1
    \$\begingroup\$ @dfhwze, I use Core 3.0 on winforms and I can confirm that it is causing the execution on the same or UI thread. If omitting you will need to use Invoke. Also not sure if the above logging excluding any framework. \$\endgroup\$ – PPann Sep 18 at 13:03
8
\$\begingroup\$

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?

\$\endgroup\$
  • 4
    \$\begingroup\$ Haha, yeah, this part is pretty scary without braces. \$\endgroup\$ – t3chb0t Sep 18 at 9:31
  • 1
    \$\begingroup\$ @t3chb0t At least there are indentations.. but the white-space police has some concerns :p \$\endgroup\$ – dfhwze Sep 18 at 10:50
  • 1
    \$\begingroup\$ Python## eyes ask for Parent == null check here :) \$\endgroup\$ – Dmitry Nogin Sep 18 at 17:32

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.