ZLogger v2 による .NET 8活用事例 と Unity C# 11対応の紹介
- 2023-12-19
C#用の新しい超高速＆低アロケーションの.NET用ロギングライブラリ、ZLogger v2を公開しました。v1からは何もかもを完全に作り替えた、最新のC#に合わせた新設計になっています。対応プラットフォームは.NET 8が最良ですが .NET Standard 2.0 以上、また Unity 2022.2 以上にも対応しています。.NET / Unityどちらもテキストメッセージと構造化ログの両方に対応しています。
新設計のキーポイントはString Interpolationの全面採用によるクリーンなシンタックスとパフォーマンスの両立です。
logger.ZLogInformation($"Hello my name is {name}, {age} years old.");
といったように書いたコードは
if (logger.IsEnabled(LogLvel.Information))
{
var handler = new ZLoggerInformationInterpolatedStringHandler(30, 2, logger);
handler.AppendLiteral("Hello my name is ");
handler.AppendFormatted<string>(name, 0, null, "name");
handler.AppendLiteral(", ");
handler.AppendFormatted<int>(age, 0, null, "age");
handler.AppendLiteral(" years old.");
}
のようにコンパイル時に分解されます。フォーマット文字列を実行時ではなくコンパイル時に展開すること、パラメーターはAppendFormatted<T>の形でジェネリクスで受け取ることによりボクシングが発生しないなど、コードからも明らかに効率的なことが見てとれます。ちなみにコンストラクターの30は文字列の長さ、2はパラメーターの数を指していて、ここから必要な初期バッファ数を算出していることも効率化の一つに繋がっています。
String Interpolation自体はC# 6.0から搭載されている機能ですが、文法上同じながらC# 10.0から強化されたString Interpolationが搭載されていて、カスタムのString Interpolationを提供することも可能になりました。
こうして得られた文字列断片とパラメーターは、最終的にはCysharp/Utf8StringInterpolationを通して文字列化せずに、直接UTF8としてStreamに書き込むことによって、高速化と低アロケーションを実現しています。
また、Structured Loggingにおいても、System.Text.JsonのUtf8JsonWriterとタイトに結びつくことにより
// 例えば {"name":"foo",age:33} のようにUtf8JsonWriterに書き込む
// Source Generator版、実際どうなってるかのイメージがとても分かりやすい。
public void WriteJsonParameterKeyValues(Utf8JsonWriter writer, JsonSerializerOptions jsonSerializerOptions)
{
writer.WriteString(_jsonParameter_name, this.name);
writer.WriteNumber(_jsonParameter_age, this.age);
}
// StringInterpolation版、ちょっと遠回りな感じですがやってることは一緒。
public void WriteJsonParameterKeyValues(Utf8JsonWriter writer, JsonSerializerOptions jsonSerializerOptions)
{
for (var i = 0; i < ParameterCount; i++)
{
ref var p = ref parameters[i];
writer.WritePropertyName(p.Name.AsSpan());
// MagicalBoxの説明は後述
if (!magicalBox.TryReadTo(p.Type, p.BoxOffset, jsonWriter, jsonSerializerOptions))
{
// ....
}
}
}
やはり直接UTF8として書き込みます。Structured Loggingは最近のトレンドなので、色々な言語のロガーに実装されていますが、パフォーマンスを両立しつつ、ここまでクリーンなシンタックスで実現できているものは他にない！という感じなのでかなり良いのではないでしょうか。
では実際ベンチマーク結果でどれぐらい？というと、アロケーションは少なくとも圧倒的です。
アロケーションは、という歯切れの悪い言い方をしているのは、念入りに高速になるよう設定したNLogが思ったよりも速かったせいですね、ぐぬぬ……。
さて、ZLoggerの特徴のもう一つは、Microsoft.Extensions.Loggingの上に直接構築していることです。通常のロガーは独自のシステムを持っていて、Microsoft.Extensions.Loggingと繋げる場合はブリッジを通します。現実的なアプリケーションでは ASP .NETを使う場合などMicrosoft.Extensions.Loggingを避けることはほぼ不可能です。.NET 8からはOpenTelemetry対応の強化やAspireなど、ますますMicrosoft.Extensions.Loggingの重要性は増しています。ZLogger v1と異なり、v2ではScopeなど、Microsoft.Extensions.Loggingの全機能に対応しています。
そして例えばSerilogのブリッジライブラリの品質は（ソースコードも確認しましたが）かなり低く、実際のパフォーマンスの数字にも現れています。ZLoggerはそうしたオーバーヘッドが一切かかりません。
また、デフォルトの設定も非常に重要です。ほとんどのロガーの標準設定は、例えばファイルストリームに書く場合は都度Flushするなど、かなり遅い設定が標準になっています。それを高速化するにはasync, bufferedを適切に調整する必要があり、かつ、取りこぼさないように終了時に確実にFlushさせる必要があるのですが、かなり難しいので、ほとんど標準設定のままの人も多いのではないでしょうか？ZLoggerではデフォルトで最高速になるように調整してあり、かつ、Microsoft.ExtensionsのDIのライフサイクルで最後のFlushも自動でかかるようになっているので、ApplicationBuilderなどでアプリケーションを構築した場合は何も意識しなくても取りこぼしは発生しません。
なお、都度Flushのパフォーマンスはストレージの書き込み性能に強く依存するため、例えば最近のマシンのM.2 SSDは非常に高速なため、ローカルでベンチマークすると意外と遅くない、といったことを確認できるかもしれません。ただし、実際にアプリケーションを配置する、例えばクラウドサーバーのストレージ性能がそこまで高いことはないので、ローカルでの結果を過信しないほうがいいでしょう。
MagicalBox
ここからは、パフォーマンスを実現した幾つかのトリックを紹介します。v1から引き継いでいるのはSystem.Threading.Channelsを活用したasyncな非同期書き込みプロセスの作成と、IBufferWriter<byte>による効率的なbufferedの利用による、Streamへの書き込み最適化ですが、説明は割愛します。
JSON化のために、パラメーターはInterpolatedStringHandlerで、一時的に値として保持します。その場合に、<T>の値をどのように保持するか、という問題がでてきます。普通に考えると、List<object>といったようなobject型で保持することになります。
[InterpolatedStringHandler]
public ref struct ZLoggerInterpolatedStringHandler
{
// あらゆる<T>の型を格納するためにobjectを使う、ボクシングが発生するので良くはない。
List<object> parameters = new ();
public void AppendFormatted<T>(T value, int alignment = 0, string? format = null, [CallerArgumentExpression("value")] string? argumentName = null)
{
parameters.Add((object)value);
}
}
それを避けるために、ZLoggerではMagicalBoxという仕組みを用意しました。
[InterpolatedStringHandler]
public ref struct ZLoggerInterpolatedStringHandler
{
// 魔法の箱に無限に詰め込む
MagicalBox magicalBox;
List<int> boxOffsets = new (); // 実際はこの辺は入念にキャッシュされています
public void AppendFormatted<T>(T value, int alignment = 0, string? format = null, [CallerArgumentExpression("value")] string? argumentName = null)
{
if(magicalBox.TryWrite(value, out var offset)) // boxingが発生しない！
{
boxOffsets.Add(offset);
}
}
}
MagicalBoxはどんな型(unmanaged型に限る)でも、ボクシングなしに書き込むことができる。というコンセプトで、その実態はbyte[]にUnsafe.Write、offsetを元にUnsafe.Readするというだけの代物です。
internal unsafe partial struct MagicalBox
{
byte[] storage;
int written;
public MagicalBox(byte[] storage)
{
this.storage = storage;
}
public bool TryWrite<T>(T value, out int offset)
{
if (RuntimeHelpers.IsReferenceOrContainsReferences<T>())
{
offset = 0;
return false;
}
Unsafe.WriteUnaligned(ref storage[written], value);
offset = written;
written += Unsafe.SizeOf<T>();
return true;
}
public bool TryRead<T>(int offset, out T value)
{
if (!RuntimeHelpers.IsReferenceOrContainsReferences<T>())
{
value = default!;
return false;
}
value = Unsafe.ReadUnaligned<T>(ref storage[offset]);
return true;
}
}
この辺はMemoryPackでの実装経験が元になっていて、うまく機能しています。
なお、実際のコードではbyte[] storageの効率的な再利用や非ジェネリクスなRead対応、Enumへの特別対応が入ったりなど、もう少し複雑なコードになってはいます。さすがに。
カスタムフォーマット文字列
ZLoggerのString Interpolationのいいところは、パラメーター値にメソッド呼び出しを含めると、LogLevelのチェックが入った後に呼び出されるので無駄な実行を防げるところです。
// これは
logger.ZLogDebug($"Id {obj.GetId()}: Data: {obj.GetData()}.");
// このようにLogLevelが有効かどうかチェックした後にメソッドが呼ばれる
if (logger.IsEnabled(LogLvel.Debug))
{
// snip...
writer.AppendFormatterd(obj.GetId());
writer.AppendFormatterd(obj.GetData());
}
しかし、メソッド呼び出しをStructured Loggingに出力した場合、ZLoggerはC# 10.0以降から追加されたCallerArgumentExpressionでパラメーター名を取得しているため、メソッド呼び出しの場合は "obj.GetId()" という微妙極まりない名前で出力されてしまいます。そこで、特殊なカスタムフォーマット文字列で別名を指定することができます。
// @name で別名を付けられる
logger.ZLogDebug($"Id {obj.GetId():@id}: Data: {obj.GetData():@data}.");
ZLoggerでは、String Interpolationの本来の式に従って、","でアラインメント、":"でフォーマット文字列を指定することができます。それに加えて特殊な指定として、フォーマット文字列を@から始めた場合はパラメーター名として出力します。
@によるパラメーター名指定とフォーマット文字列は併用することができます。
// Today is 2023-12-19.
// {"date":"2023-12-19T11:25:34.3642389+09:00"}
logger.ZLogDebug($"Today is {DateTime.Now:@date:yyyy-MM-dd}.");
もう一つ、共通の特殊なフォーマット文字列として"json"を指定するとJsonSerializeした形で出力できます（この辺はSerilogの持つ機能からインスパイアされました）
var position = new { Latitude = 25, Longitude = 134 };
var elapsed = 34;
// {"position":{"Latitude":25,"Longitude":134},"elapsed":34}
// Processed {"Latitude":25,"Longitude":134} in 034 ms.
logger.ZLogInformation($"Processed {position:json} in {elapsed:000} ms.");
特殊フォーマット文字列は、例えばログレベルやカテゴリー、日付を先頭/末尾に付与するためのPrefixFormatter/SuffixFormatterにも幾つか用意してあります。
logging.AddZLoggerConsole(options =>
{
options.UsePlainTextFormatter(formatter =>
{
// 2023-12-19 02:46:14.289 [DBG]......
formatter.SetPrefixFormatter($"{0:utc-longdate} [{1:short}]", (template, info) => template.Format(info.Timestamp, info.LogLevel));
});
});
Timestampにはlongdate, utc-longdate, dateonlyなど。LogLevelにはshortで3文字ログレベル表記(先頭の長さが一致するのでエディタで開いた時に読みやすくなる)へと変換されます。これら組み込みの特殊フォーマット文字列は、パフォーマンス最適化という意味合いもあります。例えばLogLevelは以下のようなコードになっているので、手で書式を作るよりも、事前組み込みのUTF8文字列で書き込むことで、絶対的に効率がよくなっています。
static void AppendLogLevel(ref Utf8StringWriter<IBufferWriter<byte>> writer, ref LogLevel value, ref MessageTemplateChunk chunk)
{
if (!chunk.NoAlignmentAndFormat)
{
if (chunk.Format == "short")
{
switch (value)
{
case LogLevel.Trace:
writer.AppendUtf8("TRC"u8);
return;
case LogLevel.Debug:
writer.AppendUtf8("DBG"u8);
return;
case LogLevel.Information:
writer.AppendUtf8("INF"u8);
return;
case LogLevel.Warning:
writer.AppendUtf8("WRN"u8);
return;
case LogLevel.Error:
writer.AppendUtf8("ERR"u8);
return;
case LogLevel.Critical:
writer.AppendUtf8("CRI"u8);
return;
case LogLevel.None:
writer.AppendUtf8("NON"u8);
return;
default:
break;
}
}
writer.AppendFormatted(value, chunk.Alignment, chunk.Format);
return;
}
switch (value)
{
case LogLevel.Trace:
writer.AppendUtf8("Trace"u8);
break;
case LogLevel.Debug:
writer.AppendUtf8("Debug"u8);
break;
case LogLevel.Information:
writer.AppendUtf8("Information"u8);
break;
case LogLevel.Warning:
writer.AppendUtf8("Warning"u8);
break;
case LogLevel.Error:
writer.AppendUtf8("Error"u8);
break;
case LogLevel.Critical:
writer.AppendUtf8("Critical"u8);
break;
case LogLevel.None:
writer.AppendUtf8("None"u8);
break;
default:
writer.AppendFormatted(value);
break;
}
}
.NET 8 XxHash3 + Non-GC Heap
.NET 8からXxHash3が追加されました。最速のハッシュアルゴリズムであるXxHashの最新シリーズで、小さいデータから大きいデータまで、迷ったらほぼこれ一択で問題ないだろうという性能になっています。なお、利用にはNuGetからSystem.IO.Hashingが必要なので、逆に.NET 8ではなくNET Standard 2.0でも使えます。
ZLoggerでも複数箇所で使っているのですが、その中から一例として、String Interpolationの文字列リテラルからキャッシュを取り出す処理の例を。
// $"Hello my name is {name}, {age} years old." が生成する文字列リテラルの並び(LiteralList)
// ["Hello my name is ", "name", ", ", "age", " years old."]
// これからUTF8変換済みのキャッシュ(MessageSequence)を取り出すという処理
static readonly ConcurrentDictionary<LiteralList, MessageSequence> cache = new();
// 非.NET 8版
#if !NET8_0_OR_GREATER
struct LiteralList(List<string?> literals) : IEquatable<LiteralList>
{
[ThreadStatic]
static XxHash3? xxhash;
public override int GetHashCode()
{
var h = xxhash;
if (h == null)
{
h = xxhash = new XxHash3();
}
else
{
h.Reset();
}
var span = CollectionsMarshal.AsSpan(literals);
foreach (var item in span)
{
h.Append(MemoryMarshal.AsBytes(item.AsSpan()));
}
// https://github.com/Cyan4973/xxHash/issues/453
// XXH3 64bit -> 32bit, okay to simple cast answered by XXH3 author.
return unchecked((int)h.GetCurrentHashAsUInt64());
}
public bool Equals(LiteralList other)
{
var xs = CollectionsMarshal.AsSpan(literals);
var ys = CollectionsMarshal.AsSpan(other.literals);
if (xs.Length == ys.Length)
{
for (int i = 0; i < xs.Length; i++)
{
if (xs[i] != ys[i]) return false;
}
return true;
}
return false;
}
}
#endif
XxHash3はclassなので(System.HashCodeみたいにstructが良かったなあ)、ThreadStaticで使いまわしつつ、GetHashCodeを生成しています。XxHash3はulongの出力しかありませんが、作者によると、32bitに落とす場合は特にXORとかかけることもなく直接落として問題ないそうです。
ここまでが普通の使い方ですが、.NET 8版ではエクストリームな最適化を入れました。
#if NET8_0_OR_GREATER
struct LiteralList(List<string?> literals) : IEquatable<LiteralList>
{
// literals are all const string, in .NET 8 it is allocated in Non-GC Heap so can compare by address.
// https://devblogs.microsoft.com/dotnet/performance-improvements-in-net-8/#non-gc-heap
static ReadOnlySpan<byte> AsBytes(ReadOnlySpan<string?> literals)
{
return MemoryMarshal.CreateSpan(
ref Unsafe.As<string?, byte>(ref MemoryMarshal.GetReference(literals)),
literals.Length * Unsafe.SizeOf<string>());
}
public override int GetHashCode()
{
return unchecked((int)XxHash3.HashToUInt64(AsBytes(CollectionsMarshal.AsSpan(literals))));
}
public bool Equals(LiteralList other)
{
var xs = CollectionsMarshal.AsSpan(literals);
var ys = CollectionsMarshal.AsSpan(other.literals);
return AsBytes(xs).SequenceEqual(AsBytes(ys));
}
}
#endif
List<string>?をReadOnlySpan<byte>に変換して、それでXxHash3.HashToUInt64やSeqeunceEqualを一発で呼んでます。見るからにこちらのほうが効率的なわけですが、しかし、そもそもList<string>?をReadOnlySpan<byte>に変換するのは合法なのか？と。この場合のstringの変換は、ReadOnlySpan<IntPtr>への変換という意味合いで、つまりヒープにあるstringのアドレスのリストへと変換しているという意図になります。
そこまではいいとして、問題はアドレスの比較は危険すぎないか、ということです。まず第一に、stringは文字列として同一であっても実態は別のアドレスにある場合も多い。第二に、ヒープにあるstringのアドレスは固定されていない、移動することがあるということです。辞書のキーとしてGetHashCodeやEqualsを求めるなら、アプリケーション実行中は完全に固定されていなければなりません。
ところが今回の利用例に着目すると、String Inteprolationで呼ばれるAppendLiteralはコンパイル時に handler.AppendLiteral("Hello my name is "); のように、必ず定数で渡されています。そのため同じ実体を指すことが保証されています。
[InterpolatedStringHandler]
public ref struct ZLoggerInterpolatedStringHandler
{
public void AppendLiteral([ConstantExpected] string s)
}
一応保険として、.NET 8から有効化されているConstantExpectedによって、定数だけが渡されることを明示しています。
もう一つは、そうした定数の文字列は最初からインターン化されているのですが、そのインターン化された場所が移動しないことは.NET 8まで保証されていませんでした。ところが、.NET 8からはNon-GC Heapが導入されたため、移動しないことが保証されている、といえます。
// .NET 8からは定数のGC.GetGenerationの結果がint.MaxValue(Non-GC Heapにいる)
var str = "foo";
Console.WriteLine(GC.GetGeneration(str)); // 2147483647
これによって、C#だとどうしても避けられないUTF16 StringからUTF8 Stringへの変換を、限界まで高速化することができました。なお、Source Generator版ではこのルックアップコスト自体を削れているため、ベンチマーク結果が最速であった通り、より高速です。
.NET 8 IUtf8SpanFormattable
ZLoggerでは値を文字列を通さずUTF8に直接書き込むことをパフォーマンスの柱にしています。.NET 8からIUtf8SpanFormattableという、値の汎用的なUTF8への直接変換を可能にしたインターフェイスが追加されました。ZLoggerは.NET 8以前の.NET Standard 2.0にも対応させるために、intやdoubleなど基本的なプリミティブは特殊な対応によって、UTF8への直接書き込みを実現していますが、.NET 8の場合は対応範囲がより広がるため、できれば.NET 8がお薦めです。
なお、IUtf8SpanFormattableはフォーマット文字列のalignmentには関知しないため、分離しているライブラリであるCysharp/Utf8StringInterpolationでは.NET Standard 2.0対応と同時に、alignment対応の機能も追加されたライブラリとなっています。
.NET 8 TimeProvider
TimeProviderは.NET 8から追加された時間に関するAPIの抽象化(TimeZone, Timerなども含む)となっていて、ユニットテスト等でも非常に役に立つ、今後の必須クラスです。TimeProviderは.NET 8未満でもMicrosoft.Bcl.TimeProviderを通して提供されているため、.NET Standard 2.0やUnityでも利用可能です。
そこでZLoggerではZLoggerOptionsにTimerProviderを指定することで、ログ出力の時間を固定することができます。
// Microsoft.Extensions.TimeProvider.TestingのFakeTimeProviderを使うとよりよい
class FakeTime : TimeProvider
{
public override DateTimeOffset GetUtcNow()
{
return new DateTimeOffset(1999, 12, 30, 11, 12, 33, TimeSpan.Zero);
}
public override TimeZoneInfo LocalTimeZone => TimeZoneInfo.Utc;
}
public class TimestampTest
{
[Fact]
public void LogInfoTimestamp()
{
var result = new List<string>();
using var factory = LoggerFactory.Create(builder =>
{
builder.AddZLoggerInMemory((options, _) =>
{
options.TimeProvider = new FakeTime(); // TimeProviderをカスタムのものに設定
options.UsePlainTextFormatter(formatter =>
{
// Timestampを先頭に付与
formatter.SetPrefixFormatter($"{0} | ", (template, info) => template.Format(info.Timestamp));
});
}, x =>
{
x.MessageReceived += msg => result.Add(msg);
});
});
var logger = factory.CreateLogger<TimestampTest>();
logger.ZLogInformation($"Foo");
Assert.Equal("1999-12-30 11:12:33.000 | Foo", result[0]);
}
}
ログ出力の完全一致でのテストが必要……！などといった場合に有効に使うことができます。
Source Generator
Microsoft.Extensions.Loggingではハイパフォーマンスなログ出力のためにLoggerMessageAttributeとSource Generatorが標準で提供されています。
これは確かにUTF16文字列の生成では非常に優秀ですが、Structured Logging生成部分に関しては疑問符がつきます。
// このpartial methodは
[LoggerMessage(LogLevel.Information, "My name is {name}, age is {age}.")]
public static partial void MSLog(this ILogger logger, string name, int age, int other);
// このクラスを生成する
private readonly struct __MSLogStruct : global::System.Collections.Generic.IReadOnlyList<global::System.Collections.Generic.KeyValuePair<string, object?>>
{
private readonly global::System.String _name;
private readonly global::System.Int32 _age;
public __MSLogStruct(global::System.String name, global::System.Int32 age)
{
this._name = name;
this._age = age;
}
public override string ToString()
{
var name = this._name;
var age = this._age;
return $"My name is {name}, age is {age}."; // 文字列生成は高速そう（C# 10.0のString Interpolation Improvementsにベタ乗りなので言うことなし！）
}
public static readonly global::System.Func<__MSLogStruct, global::System.Exception?, string> Format = (state, ex) => state.ToString();
public int Count => 4;
// こちらがStrcuted Loggingのコードですが、ん……？
public global::System.Collections.Generic.KeyValuePair<string, object?> this[int index]
{
get => index switch
{
0 => new global::System.Collections.Generic.KeyValuePair<string, object?>("name", this._name),
1 => new global::System.Collections.Generic.KeyValuePair<string, object?>("age", this._age),
2 => new global::System.Collections.Generic.KeyValuePair<string, object?>("other", this._other),
3 => new global::System.Collections.Generic.KeyValuePair<string, object?>("{OriginalFormat}", "My name is {name}, age is {age}."),
_ => throw new global::System.IndexOutOfRangeException(nameof(index)), // return the same exception LoggerMessage.Define returns in this case
};
}
public global::System.Collections.Generic.IEnumerator<global::System.Collections.Generic.KeyValuePair<string, object?>> GetEnumerator()
{
for (int i = 0; i < 4; i++)
{
yield return this[i];
}
}
global::System.Collections.IEnumerator global::System.Collections.IEnumerable.GetEnumerator() => GetEnumerator();
}
[global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "8.0.9.3103")]
public static partial void MSLog(this global::Microsoft.Extensions.Logging.ILogger logger, global::System.String name, global::System.Int32 age)
{
if (logger.IsEnabled(global::Microsoft.Extensions.Logging.LogLevel.Information))
{
logger.Log(
global::Microsoft.Extensions.Logging.LogLevel.Information,
new global::Microsoft.Extensions.Logging.EventId(764917357, nameof(MSLog)),
new __MSLogStruct(name, age),
null,
__MSLogStruct.Format);
}
}
KeyValuePair<string, object?> ということで、基本的に普通に作るとボクシングは避けられません、しょーがない。
そこで、ZLoggerでは似たようなSource Generator属性であるZLoggerMessageAttributeを提供しています。これにより、UTF8最適化、ボクシングレスなJSONロギングを可能にしています。
// LoggerMessageをZLoggerMessageに変えるだけ
// なお、ZLoggerMessageのフォーマット文字列部分では、String Interpolation版と同じように@による別名やjsonによるJSON化も可能
[ZLoggerMessage(LogLevel.Information, "My name is {name}, age is {age}.")]
static partial void ZLoggerLog(this ILogger logger, string name, int age);
// このようなコードが生成される
readonly struct ZLoggerLogState : IZLoggerFormattable
{
// JSON用にJsonEncodedTextを事前生成
static readonly JsonEncodedText _jsonParameter_name = JsonEncodedText.Encode("name");
static readonly JsonEncodedText _jsonParameter_age = JsonEncodedText.Encode("age");
readonly string name;
readonly int age;
public ZLoggerLogState(string name, int age)
{
this.name = name;
this.age = age;
}
public IZLoggerEntry CreateEntry(LogInfo info)
{
return ZLoggerEntry<ZLoggerLogState>.Create(info, this);
}
public int ParameterCount => 2;
public bool IsSupportUtf8ParameterKey => true;
public override string ToString() => $"My name is {name}, age is {age}.";
// テキストメッセージはUTF8への直接書き込み
public void ToString(IBufferWriter<byte> writer)
{
var stringWriter = new Utf8StringWriter<IBufferWriter<byte>>(literalLength: 21, formattedCount: 2, bufferWriter: writer);
stringWriter.AppendUtf8("My name is "u8); // u8でリテラルは直接書き込み
stringWriter.AppendFormatted(name, 0, null);
stringWriter.AppendUtf8(", age is "u8);
stringWriter.AppendFormatted(age, 0, null);
stringWriter.AppendUtf8("."u8);
stringWriter.Flush();
}
// JSON出力の場合はUtf8JsonWriterに直接書き込むことで完全にボクシング避け
public void WriteJsonParameterKeyValues(Utf8JsonWriter writer, JsonSerializerOptions jsonSerializerOptions, IKeyNameMutator? keyNameMutator = null)
{
// 型によって呼び出すメソッドは異なる(WriteString, WriteNumber, etc...)
writer.WriteString(_jsonParameter_name, this.name);
writer.WriteNumber(_jsonParameter_age, this.age);
}
// 以下にMessagePack対応などの拡張用のメソッドが実際には生成されますが省略
}
static partial void ZLoggerLog(this global::Microsoft.Extensions.Logging.ILogger logger, string name, int age)
{
if (!logger.IsEnabled(LogLevel.Information)) return;
logger.Log(
LogLevel.Information,
new EventId(-1, nameof(ZLoggerLog)),
new ZLoggerLogState(name, age),
null,
(state, ex) => state.ToString()
);
}
Utf8JsonWriterに直接書く、また、キー名はJsonEncodedTextを事前に生成して持っておく、という仕様によってJSON化のパフォーマンスを最大化しています。
また、Structured LoggingはJSONに限らず他のフォーマットもありえます。例えばMessagePackを利用することで、より小さく、より高速にすることができるでしょう。ZLoggerでは、そうしたJSON特化のようなビルトインではないプロトコルへの出力においてもボクシングを避けるためのインターフェイスが定義されています。
public interface IZLoggerFormattable : IZLoggerEntryCreatable
{
int ParameterCount { get; }
// メッセージ出力に使う
void ToString(IBufferWriter<byte> writer);
// JSON出力に使う
void WriteJsonParameterKeyValues(Utf8JsonWriter jsonWriter, JsonSerializerOptions jsonSerializerOptions, IKeyNameMutator? keyNameMutator = null);
// それ以外の構造化ログ出力に使う
ReadOnlySpan<byte> GetParameterKey(int index);
ReadOnlySpan<char> GetParameterKeyAsString(int index);
object? GetParameterValue(int index);
T? GetParameterValue<T>(int index);
Type GetParameterType(int index);
}
ちょっと変わったインターフェイスになっていますが、以下のようなループを回すことでボクシングの発生をなくせます。
for (var i in ParameterCount)
{
var key = GetParameterKey(i);
var value = GetParameterValue<int>();
}
こうした設計はADO.NETのIDataRecordの使い方と同じ設計です。また、Unityでもネイティブ→マネージドでの配列のアロケーションを避けるために、インデックス経由で取得することがよくあります。
Unity
UnityはUnity 2023の時点でも正式な対応C#のバージョンは9.0です。ZLoggerはC# 10.0以上のString Interpolationが大前提となっているので、普通は動きません。普通は。ところが、正式にアナウンスはされていないのですが Unity 2022.2 から同梱されているコンパイラのバージョンが上がっていて、内部的にはC# 10.0でコンパイル可能になっていることを発見しました。
csc.rsp ファイルによってコンパイラオプションを渡すことができるので、そこで明示的に言語バージョンを指定してあげると、C# 10.0の全ての文法が利用可能になります。
-langVersion:10
このままだと出力されるcsprojには依然として<LangVersion>9.0</LangVersion>が指定されているため、IDE上ではC# 10.0で書けません。そこでCysharp/CsprojModifierを用いて、LangVersionを上書きしてしまいましょう。以下のようなLangVersion.propsというファイルを作成して、CsprojModifierに混ぜてもらえば、IDE上でもC# 10.0として記述できるようになります。
<Project xmlns="http://schemas.microsoft.com/developer/msbuild/2003">
<PropertyGroup>
<LangVersion>10</LangVersion>
<Nullable>enable</Nullable>
</PropertyGroup>
</Project>
Unity向けにはAddZLoggerUnityDebugという拡張を追加してあるので、
// こんなグローバルのユーティリティーを用意してあげて
public static class LogManager
{
static ILoggerFactory loggerFactory;
public static ILogger<T> CreateLogger<T>() => loggerFactory.CreateLogger<T>();
public static readonly Microsoft.Extensions.Logging.ILogger Global;
static LogManager()
{
loggerFactory = LoggerFactory.Create(logging =>
{
logging.SetMinimumLevel(LogLevel.Trace);
logging.AddZLoggerUnityDebug(); // log to UnityDebug
});
Global = loggerFactory.CreateLogger("Logger");
Application.exitCancellationToken.Register(() =>
{
loggerFactory.Dispose(); // flush when application exit.
});
}
}
// 例えばこんな感じに使ってみる
public class NewBehaviourScript : MonoBehaviour
{
static readonly ILogger<NewBehaviourScript> logger = LogManager.CreateLogger<NewBehaviourScript>();
void Start()
{
var name = "foo";
var hp = 100;
logger.ZLogInformation($"{name} HP is {hp}.");
}
}
なお、C# 10.0のString Interpolation性能向上の恩恵を受けれるのはZLogを使った場合のみの話で、通常のString生成にString Interpolationを使っても性能向上はしません。string生成の性能向上にはランタイムにDefaultInterpolatedStringHandlerが必要で、これは .NET 6 以上にのみ同梱されているからです。DefaultInterpolatedStringHandlerが存在しない場合は今まで通りのstring.Formatにフォールバックされるため、普通にボクシングされます。
JSONによる構造化ログや出力のカスタマイズ、ファイルへの出力などにも全て対応しています。
var loggerFactory = LoggerFactory.Create(logging =>
{
logging.AddZLoggerFile("/path/to/logfile", options =>
{
options.UseJsonFormatter();
});
});
そしてもう一つボーナスとして、Unity 2022.3.12f1 以上だとC#のコンパイラバージョンがもう少し上がっていて、-langVersion:previewを指定するとC# 11.0が使えます。また、ZLoggerのSource Generatorが自動で有効になっているので、[ZLoggerMessage]を使って生成することができます。
public static partial class LogExtensions
{
[ZLoggerMessage(LogLevel.Debug, "Hello, {name}")]
public static partial void Hello(this ILogger<NewBehaviourScript> logger, string name);
}
Source Generatorの生成するコードがC# 11.0を要求するので(UTF8 String Literalなどを多用しているため)、[ZLoggerMessage]が使えるのはUnity 2022.3.12f1 以上限定となります。
なお、Unityには同種の標準ロギングライブラリとしてcom.unity.loggingがリリースされています。同じように構造化ロギングやファイル出力が可能なほか、Source Generatorを使ってクラスそのものを自動生成して、メソッドのオーバーロードを引数に応じて生成することで値のボクシング避けをするといった、面白い設計をしていました。Burst云々という話がよく出てきますが、このSource Generatorの大胆な使い方のほうがパフォーマンスの肝だと思います。ZLoggerはC# 10.0のString Interpolationを活用しているわけですが、そういうアプローチでの回避策というのはちょっと考えたことがなかったので、かなり目から鱗です。パフォーマンス的にもかなり練られています。
ZLoggerのほうがString Interpolationによる書き味は上、パフォーマンスは、まぁいい勝負するんじゃないかなとは思いたいんですが、どうでしょうね……？
NuGetForUnity
今回Unityへのライブラリの配布はNuGetForUnityを採用しました。これは普通の.NETライブラリへの依存が多いものへの配布に非常に便利で、NuGetForUnityを入れたあとに、GUIでZLoggerをこうして入れると
こんなように依存関係も解決して、Assets/Packagesの下にDLLがばらまかれます。
Source Generatorが含まれている場合は、ちゃんとRoslynAnalyzerのラベルも付与してくれるので、そのままSource GeneratorもUnity上で有効化されています。
良い点としては、やはり大量のマネージドDLLの管理を一括でやってくれることと、動作がシンプル（基本的には解決したファイルをAssets/Packagesにばらまくだけ)なのでやっていることがイメージつきやすいところです。同じようなツールとしてUnityNuGetというものがあるのですが、そちらは独自レジストリに配布しているファイルを引っ張ってくるという作りなので、NuGetForUnity(MS公式のNuGetのレジストリから引っ張ってくる)のほうが素直な挙動で好ましく思います。
反面、UnityEngine.dllに依存したコードやUnityのバージョンで分岐するコードは配りにくいところがあります。ZLoggerではそのためのファイル(ZLoggerUnityDebugLoggerProvider)は別途git参照で引っ張ってくるハイブリッド方式での配布としました。かなりバランスの良いやり方かなと思うんですがどうでしょう……？特にCysharpのライブラリはコア部分はUnity非依存のものが多いので、問題なければ今後のCysharpのライブラリはこの形式での配布を基本としていきたいところです。
ライブラリ作者側としては、コア部分はDLLで配ることになるのでC# 12のままで良い（今まではUnityのためにC# 9にダウングレードさせて書いたりしてた）のが、とにかくとても楽ですね……！
まとめ
この記事はC# Advent Calendar 2023の12月3日分の記事となります。すごい遅刻ですが間に合ったので（？）よし。よくない。
なお、ZLogger v2の作成にあたっては VContainer や VYaml で有名な @hadashiA さんに、アイディア出しから細かい実装、度重なる仕様のちゃぶ台返しに付き合ってもらいました。今回のv2は非常に完成度高くなったと思うのですが、自分一人ではここまで達しなかったので大変感謝です。
ともあれZLoggerは使いやすさでもパフォーマンスでも最強！のロガーに仕上がったと思いますので、是非使ってみてください。