超高速なloggerを作ってみたくて

超高速なLoggerに唐突に興味を持つ。 Log4J2が非常に高速であり、性能を気にするなら、基本的にはLog4J2を使えば良いが、柔軟性を捨ててでもより高速なLoggerは作れないかと考えてみた。 なお、kotlin/jvm(java8)で実装。

参考資料は、以下のページ。 logging.apache.org

www.matthicks.com

www.sitepoint.com

要件は以下の通り。

  • レイアウト(項目の出力順序)は固定: 日時、ログレベル、マーク、出力箇所(クラス名、メソッド名、行番号)、ログメッセージ
  • 日時フォーマットは固定: yyyy/MM/dd HH:mm:ss.SSS
  • ログメッセージ方法は全てラムダによる遅延生成を必須化
  • ImmediateFlushはfalse固定
  • appenderは、ローリングファイルアペンダー相当

簡易実装の結果としては、自宅のwindows-pcにて同期ロギング(not asyncLogger)/非同期ファイル出力(ImmediateFlushはfalse)、シングルスレッドにて170万msg/sを達成した。なお、同一マシンでのlog4j2の測定は、まだ未実施なので、比較はこれからだが、一応、上述のlog4j2のページの数字よりは良い結果が出た。 ちなみに、ログの出力箇所(行番号とか)を出そうとすると、log4j2とかでもすごく遅くなるため、この簡易ロガーは、行番号出力という観点においては、少なくとも世界で2番目ぐらいには速い。(一番は、参考資料にある通りに、コンパイル時決定を行うscribe2でしょ、きっと。)

チューニングした内容は以下の通り。キャッシュ化は、ThreadLocalを利用。

  • LogEventのキャッシュ化: ほぼ効果なし(気休め?)
  • StringBuilderのキャッシュ化: 効果あり
  • Calendarのキャッシュ化: 効果あり
  • 現在時刻と前回時刻を見て日時の再文字列化コストの削減: 効果あり
  • DateFormatを使わず、固定フォーマットのハードコーディング: 効果あり
  • 日付変換処理において、割り算を減らす(/10と%10): 効果あり
  • 出力箇所のキャッシュ化: 効果あり。ただし、ラムダ式が個別クラスにて実現される仕様に依存。コンパイル時マクロとかあれば・・・。

というか、これだけやっても、上述の参考資料のlog4j2の数字よりも30%ぐらいしか速くならないって、log4j2はどんだけ化け物なのかがよく分かった。

思いつく範囲で、今後のチューニング予定は以下の通り。 ただ、上述のチューニングを実施して、ファイル出力なしのときの性能が10倍近くになっているので、これ以上は多くは望めないところが悲しい。(例:StringBuilder、LogEvent、再文字列化コスト削減の3つで、ファイル出力なしの1回のロギングあたり380ns→90ns。自分のマシンとしては300clockぐらいしか使ってないことになるが、本当か? キャッシュヒット次第で吹っ飛ぶクロック数だが・・・) 残りのボトルネックはファイル出力なので、これ以上はマルチスレッド時の高速化ぐらいしかないかなあ。

  • StringBuilderを止めて、CharBufferを使う
  • ログレベルの文字列書き込みや出力箇所とかの再文字列化コストの削減
  • String生成コストが一定以上あるため、出力方法をPrintWriterから他のに変える(この場合のStackTraceをどうするかは別に考える。諦めるのも有りか?)
  • マルチスレッド環境向けのチューニング(現状は出力手前でsynchronizedしてる)。要は、ログ出力呼出と実際の出力の非同期化。AsyncLoggerと同じ理屈。
  • ガベージフリーをもう少し努力する(相当キャッシュ化したので、あとはファイル出力周りとか、一時オブジェクトの生成が発生しないよう努力?)