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()}");
 }
}

• dfhwze: I nominate this as question of the day I need some time to study AsyncLocal :p
• Walter Vehoeven: 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
• t3chb0t: @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: github.com/he-dev/reusable/blob/dev/Reusable.OmniLog/src/… @dfhwze this is the helper that encapsulates that logic
• Walter Vehoeven: @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.

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?

• t3chb0t: Haha, yeah, this part is pretty scary without braces.
• dfhwze: @t3chb0t At least there are indentations.. but the white-space police has some concerns :p
• Dmitry Nogin: Python## eyes ask for Parent == null check here :)