# Operation logger

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())
from i in Range(0, 4)
select AlphaAsync());
}

{
using (new Op("Alpha function"))
await BetaAsync();
}

{
using (var op = new Op())
{
op.Trace("Waiting...");
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()}");
}
}

• I nominate this as question of the day I need some time to study AsyncLocal :p – dfhwze Sep 18 '19 at 6:43
• 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 – Walter Vehoeven Sep 18 '19 at 7:11
• @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 :-) – t3chb0t Sep 18 '19 at 8:59
• github.com/he-dev/reusable/blob/dev/Reusable.OmniLog/src/… @dfhwze this is the helper that encapsulates that logic – t3chb0t Sep 18 '19 at 9:09
• @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. – Walter Vehoeven Sep 18 '19 at 13:03

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)

No-one has died from using some {}-braces. Why not use them?
• Python## eyes ask for Parent == null check here :) – Dmitry Nogin Sep 18 '19 at 17:32