Proposal: Simple changes to vastly improve FormattableString

[rikimaru0345]

I designed this idea with full backwards compatibility in mind, since I know that the design team wants to (or rather "has to") keep the old code around.

There are a variety of problems regarding string interpolations
and obviously many people have the same issues with it. (see: #675 https://github.com/dotnet/roslyn/issues/12336 #177 )

---

Issue

The main issue here is performance (which is terrible when FormattableString is used in trace-logging).
Objects get allocated even when a log level is turned of.
Expressions inside the interpolations are evaluated even when their results are not needed.

Proposal

Introduce a mechanic that can exist side-by-side with FormattableString, so people who want to override things and create their own FormattableStringFactory for whatever reason, can still do so.

However it seems like a vast majority of people want something different from string interpolation.

I will roughly outline how I imagine that could work and I'd be very happy to hear your thoughts and suggestions.

Intended usage scenario

After reading through a ton of comments on the issues with string interpolation and FormattableString
I feel confident in saying that most people imagine a usage-scenario similar to this:

log.Info($"Some string {num.SomeMethod(x)} abcdef");

We do not want the interpolation (num.SomeMethod(x)) to be executed if Info() decides that it doesn't want to actually output the message.

That means Info has to take some sort of description of the string interpolation instead of the fully evaluated arguments + the format string.

Manually checking like if(log.IsInfoEnabled) log.Info(...); is really tiresome and makes the code larger for no real reason.

Currently the best way to do this is to simply not use string-interpolation at all, which is sad
and actually doesn't even avoid the problem of calculating things when they're not needed.
log.Info("current way of doing this {0}, {1}, {2}", a,b c);

There are a lot of scenarios where we have debug/trace/verbose logging and when those get disabled we don't want to evaluate expressions that end up not being used.

Goals

• Should work hand-in-hand with logging libraries/methods/classes.
• Should not allocate anything except what is absolutely necessary. (should use structs/ref/... whenever possible)
• Should not call interpolations inside the string until absolutely needed.
• As before we obviously want the ability to call string.Format ourselves with whatever culture we want (or maybe use a StringBuilder or something instead, if one wants to do that!).

Implementation

When a interpolation is calling a method (like in the example above), then the expression gets refactored into a real method (just like lambda expressions). A delegate is then passed to the Info function.

The Info method could be declared like one of the following examples:

public void Info1(string formatString, Func<object[]> calculateInterpolations) { ... }


struct Interpolations<T1, T2, T3, ...> // [CompilerGenerated]
{ 
  public readonly Func<T1> GetFirst(); // Func when its a expression
  public readonly T2 Second; // Direct value when its a variable
  // ...
}
public void Info2(string formatString, Interpolations interpolations) { ... }


public void Info3(string formatString, params Func<object> args) {...} // The compiler would wrap even normal variables into delegates.

I'm not sure which one of those methods would be easiest to implement or fulfill the proposed goals best, but I'm sure that together we can come up with something that will actually satisfy the majority of people.

[yaakov-h]

I don't understand your Implementation section at all.

Also, what's wrong with Info(Func<IFormattable>) or Info(Func<FormattableString>)?

[rikimaru0345]

Func<IFormattable> would indeed defer the evaluation of the parameter(s), but having an IFormattable, FormattableString, or Func<> at all means you have at least one more allocation that could be potentially avoided.

For scenarios where you really want to avoid all unnecessary allocations (DSP code, or also in Unity3D) that can make a huge difference.
And you'd also allocate the delegate Func<...> every time as well.
And another allocation for the arguments in FormattableString.Create() (where it does new object[] ...).

In my example implementations I try to avoid allocating a FormattableString as well as an array for the arguments by letting the compiler create a suitable value-type.
However it seems that in order to defer the evaluation you always need to allocate at least one Func<> or other type of delegate.

[svick]

Could you clarify what exactly are the options you're proposing, and, since one of the goals is to avoid allocations, how do they compare in that regard with alternative approaches, like using Func<string>? (Which, in the case of closing over a local variable, allocates the delegate, the closure, and also whatever is necessary to invoke string.Format.)

I especially don't understand how is Interpolations supposed to work, since it seems to be a type generated by the compiler based on the specific interpolated string, but the method using it can't directly depend on that.

[mattwar]

Except for very expensive inline expressions within interpolated strings, you still end up allocating a function that wraps over the locals used. So it probably saves you a bunch sometimes, but not much most of the time. If you are really worried about allocation performance, you'd be better off surrounding the log method invocation with an if statement that tests whether you should be emitting to the log at all. That way, no allocations occur, and you can use the interpolated string as is.

[DerpMcDerp]

This proposal blockades more efficient implementations of the rare conditional expression evaluation problem.

e.g. I made a toy programming language that had a dtrace statement acts as if you did:

expr1;
// dtrace("some string", a, foo())
// is syntax sugar for:
if (isTracing)
	print("some string", a, foo());
expr2;
expr3;
return;

And the way it was actually implemented was that the code would generate something akin to:

	expr1;
	expr2; // this instruction
_expr3:
	expr3;
	return;
	...
_debugtrace:
	expr2;
	print("some string", a, foo());
	goto _expr3;

And when isTracing was set to true, the runtime would hotpatch the code to look like:

	expr1;
	goto _debugtrace; // gets patched to this
_expr3:
	expr3;
	return;
	...
_debugtrace:
	expr2;
	print("some string", a, foo());
	goto _expr3;

So that the trace logging code would be outside the instruction cache completely in the common case of no trace logging.

[amis92]

If so much stress is put on efficiency, why not use the simplest method already available:

interface ILogger
{
  ILevelLogger Debug { get; }
  ILevelLogger Trace { get; }
  ILevelLogger Verbose { get; }
  ILevelLogger Info { get; }
  // etc for each level
}

interface ILevelLogger
{
  void Msg(string message);
  void Exc(string message, Exception exception);
  // any other methods you want
}

// usage
ILogger Log = GetLogger();
var stuff = DoStuff();
Log.Debug?.Msg($"Stuff done, max result: {stuff.Max()}");

ILogger interface returns null ILevelLogger for levels not actually being logged, so you can use null-conditional operator to short-circuit. If Debug returns null, stuff.Max() won't execute.

Profit!
🙌

[dzmitry-lahoda]

Stuctured logging is fun.

Wrong(GC object created, should be replaced with several Appends)

 private static StringBuilder logBuilder;

 logBuilder.AppendFormat($"{timestamp} [{logLevel}] {message} [{eventId}]");

People think they to Format, but they do not.

https://stackoverflow.com/questions/710504/stringbuilder-append-vs-stringbuilder-appendformat/710571#710571

Or is next right?

 logBuilder.AppendFormat(null, $"{timestamp} [{logLevel}] {message} [{eventId}]");
 logBuilder.AppendFormat("{0}", $"{timestamp} [{logLevel}] {message} [{eventId}]");

Wrong - structure does not get into index:

Log($"server time: {serverTimeStamp} server time stamp: {currentServerTime}");

People think they do structured logging, but they do not.

Right - structure get into index:

 Log("server time: {serverTimeStamp} server time stamp: {currentServerTime}", serverTimeStamp, currentServerTime);

? - structure gets into index, better refactoring, but long string and GC

Log($"Lobby {{{nameof(name)}}}. Skipping client command with tick {{{nameof(commandTick)}}}. ", name, commandTick)

#384

Should I write for each method something like LogFormat(FormattableString x)? But where are names? Why it still not done?

dotnet/roslyn#142

Conclusion

C# or BCL must be improved. Interpolation should have API which is used. In StringBuilder or Microsoft Extensions Logging.