I'm trying to avoid evaluating and passing strings to a separate static class, if flags set in that class would skip using the strings anyway. Doing basic perf measurements with System.Diagnostics.Stopwatch. A C# .NET Framework 4.8 library that's a plugin for a speech recognition app.
The plugin makes many calls to a static class, passing various evaluated strings. Different calls are filtered based on static states set in that class, so the strings are only used if a matching static bool is true. For example
Logger.MenuWrite(string msg) will only log the string if Logger.MenuItems is true.
From the Stopwatch measurements I think the strings are always getting evaluated regardless of whether the Logger class will not be using them (that is, I don't think JIT isn't inlining). Though the perf hit of this is slight, I'm trying to get every millisecond I can as I scale this up.
What I've tried and test so far:
I added Stopwatch measurements around some loops that made a lot of Logger.MenuWrite() calls while Logger.MenuItems was false, then measured the same loop with the check for Logger.MenuItems done inline for each call, and saw a definite, repeatable difference - about a millisecond less per 1000 calls with strings that had only a single evaluated field.
I first tried [MethodImpl(MethodImplOptions.AggressiveInlining)] on the static methods in the Logger class like so:
[MethodImpl(MethodImplOptions.AggressiveInlining)]
public static void MenuWrite(string msg)
{
if (s_MenuItems )
{ vaProxy.WriteToLog(s_Prefix + msg); }
}
This cut the time for the loop in half, but that is still about 1/2 a millisecond more than if I have an actual direct check in the loop, like:
if (Logger.MenuItems) { Logger.MenuWrite(msg); }
So I tried using Delegates, like so:
static Action<string> LogIfMenu = (msg) =>
{
if (Logger.MenuItems) { Logger.MenuWrite(msg); }
};
But using LogIfMenu call seemed to have the same or worse performance than using [MethodImpl(MethodImplOptions.AggressiveInlining)].
Any thoughts on what's causing the perf hit - string evaluation/creation, method calls, something else? Would appreciate any advice or options, beyond inlining all the calls by hand. Thanks.
EDITS:
$"Passed: {Cmd.Observable} and {Cmd.Dist}"EDIT: Modified small reproducible example to be console app.
// File1.cs
namespace CS_Console_Test_05
{
static public class Logger
{
public static bool MenuItems = false;
public static void MenuWrite(string msg)
{
if (MenuItems) { Console.WriteLine(msg); }
}
}
}
// File2.cs
namespace CS_Console_Test_05
{
internal class Program
{
public static void LoopMessagesInline()
{
Stopwatch sw = new Stopwatch();
sw.Start();
for (int i = 0; i < 10000; i++)
{
if (Logger.MenuItems)
{ Logger.MenuWrite($"Counting Down to the time {sw.Elapsed}"); }
}
sw.Stop();
Console.WriteLine($"Inline Elapsed = {sw.Elapsed}");
}
public static void LoopMessagesCall()
{
Stopwatch sw = new Stopwatch();
sw.Start();
for (int i = 0; i < 10000; i++)
{
Logger.MenuWrite($"Counting Down to the time {sw.Elapsed}");
}
sw.Stop();
Console.WriteLine($"Called Elapsed = {sw.Elapsed}");
}
static void Main(string[] args)
{
do
{
Console.WriteLine("Enter Value for MenuItems:");
string miRead = Console.ReadLine();
Logger.MenuItems = (miRead.Equals("Kludge")); // so JIT won't know if true or false
Console.WriteLine("'x' to quit, SPACE for Inline, nothing for Call, then ENTER: ");
string way = Console.ReadLine();
way = way.ToLower();
if (way.Equals(" "))
{ LoopMessagesCall(); }
else if (way.Equals("x"))
{ return; }
else
{ LoopMessagesInline(); }
} while (true);
}
}
}
Calls to LoopMessageInline() take about 7-8 milliseconds. Calls to LoopMessageCall() take less than 1 millisecond.
As mentioned above, neither MethodImplOptions.AggressiveInlining, nor using Delegates seems to help with this.
First of all use proper benchmarking tools - like BenchmarkDotNet.
I have come up with the following benchmark:
namespace CS_Console_Test_05
{
static public class Logger
{
public static bool MenuItems = false;
[MethodImpl(MethodImplOptions.AggressiveInlining)]
public static void MenuWrite(string msg)
{
if (MenuItems)
{
Console.WriteLine(msg);
}
}
[MethodImpl(MethodImplOptions.AggressiveInlining)]
public static void MenuWriteFormattableString(FormattableString msg)
{
if (MenuItems)
{
Console.WriteLine(msg);
}
}
[MethodImpl(MethodImplOptions.AggressiveInlining)]
public static void MenuWriteFunc(Func<string> msg)
{
if (MenuItems)
{
Console.WriteLine(msg());
}
}
}
}
[MemoryDiagnoser]
public class LoggerWrapperBench
{
public static string Value = "TestVal";
private const int Iterations = 1000;
[Benchmark]
public void LoopMessagesInline()
{
for (int i = 0; i < Iterations; i++)
{
if (Logger.MenuItems)
{
Console.WriteLine($"Counting Down to the time {Value}");
}
}
}
[Benchmark]
public void LoopMessagesInlineFormatableString()
{
for (int i = 0; i < Iterations; i++)
{
Logger.MenuWriteFormattableString($"Counting Down to the time {Value}");
}
}
[Benchmark]
public void LoopMessagesInlineFunc()
{
for (int i = 0; i < Iterations; i++)
{
Logger.MenuWriteFunc(() => $"Counting Down to the time {Value}");
}
}
[Benchmark]
public void LoopMessagesCall()
{
for (int i = 0; i < Iterations; i++)
{
Logger.MenuWrite($"Counting Down to the time {Value}");
}
}
}
Which gives on my machine:
| Method | Mean | Error | StdDev | Gen0 | Allocated |
|---|---|---|---|---|---|
| LoopMessagesInline | 524.7 ns | 10.10 ns | 10.37 ns | - | - |
| LoopMessagesInlineFormatableString | 10,908.3 ns | 215.37 ns | 328.89 ns | 10.1929 | 64000 B |
| LoopMessagesInlineFunc | 1,031.8 ns | 18.34 ns | 21.12 ns | - | - |
| LoopMessagesCall | 14,523.6 ns | 286.28 ns | 391.86 ns | 14.0228 | 88000 B |
Making the lazy func approach closest to the inline one (though I wonder a bit why it does not allocate anything).
Note that inlining does not have much effect on string evaluation in case of MenuWrite and MenuWriteFormattableString because:
var s = DoSomething(); // like build string
if(...)
{
Console.WriteLine(s);
}
And
if(...)
{
Console.WriteLine(DoSomething());
}
Are not functionally equivalent in general case (due to possible side effects of the function call), so inlining should not change correctness of the program, so the string formatting gets called (at least it's my theory on the subject).
UPD
There is one more approach worth mentioning (though I was not able to make it perform faster and it can even preform even slower in case of multiple interpolated elements) - since .NET 6 you can create a custom interpolated string handler:
[InterpolatedStringHandler]
public readonly ref struct LogInterpolatedStringHandler
{
readonly StringBuilder? _builder;
public LogInterpolatedStringHandler(int literalLength, int formattedCount)
{
if (Logger.MenuItems)
{
_builder = new StringBuilder(literalLength);
}
}
public void AppendLiteral(string s) => _builder?.Append(s);
public void AppendFormatted<T>(T t) => _builder?.Append(t?.ToString());
internal string GetFormattedText()
{
if (_builder is not null)
{
var format = _builder.ToString();
Console.WriteLine(format);
return format;
}
return string.Empty;
}
}
And usage:
[MethodImpl(MethodImplOptions.AggressiveInlining)]
public static void MenuWriteInterpolatedStringHandler(ref LogInterpolatedStringHandler msg)
{
if(MenuItems) msg.GetFormattedText();
}
[Benchmark]
public void LoopMenuWriteInterpolatedStringHandler()
{
for (int i = 0; i < Iterations; i++)
{
Logger.MenuWriteInterpolatedStringHandler($"Counting Down to the time {Value}");
}
}
Which gives on my machine:
| Method | Mean | Error | StdDev | Allocated |
|---|---|---|---|---|
| LoopMenuWriteInterpolatedStringHandler | 1,690.0 ns | 32.63 ns | 36.27 ns | - |
| LoopMessagesInline | 534.2 ns | 10.39 ns | 15.22 ns | - |