お疲れ様です。バスクリンです。
前回のアドカレでネタを探しに猫カフェに行ってきましたが、次の週にまた行ってしまいました！福岡から大阪に来られているSさんと大阪メンバーでにゃんこに突撃です。噛みつかれた人続出でしたが、めっちゃ楽しかったです。大阪ではちょっとしたにゃんこブーム到来です。
今回はアドベントカレンダー空いていたので、ログの話をしてみようと思います。今回はかなり長めになっています。
ログ出力
この業界にいる人なら一回は使ったことある機能ですよね。
ログの目的は処理のトレースや確認・通知、障害発生時の問題の切り分けなど、システムを作成するにはなくてはならない機能です。ただし、システム要件に必須かと言えば必須ではなく、エンジニア側の防衛策に近いものがあります。
ログの種類
ログの種類にも色々あって、出力先と用途によって分類することができます。
出力先
- ファイル
- 標準エラー出力
- イベントログ
- メールやIPMessanger通知など
用途
- 処理のトレース
- エラー、例外発生時のダンプ、コールスタック
- レスポンス、トラフィック等の出力
ログの重要性
ログ出力の設計は重要でしょうか？答えはYESです。ログは直接業務要件に必要ない機能なので、設計がおろそかになりがちですが、非常に重要なウェイトを占めています。
ある現場の話です。そのシステムはメイン画面が表示するまで30分以上かかる巨大なシステムでした。CPUはIntel Core i7の8コア、当時でも相当なハイパフォーマンスPCでしたが、それでも30分以上かかっていました。ログファイルを見ると20種類くらいのログが出力されていて、一番大きなログファイルは1GB以上出力されていました。
ログファイルの出力がボトルネックだと判断して、パフォーマンス改善としてログ出力を再設計しました。
- ログ出力のIO部分は別スレッドで管理
- ファイルのオープンは最小限にする
- メインスレッドのログ出力はメールスロット投げつける（本来なら共有メモリ経由とかでやりたかったけど、納期の関係でメールスロットにしました）
- ログスレッドは一定間隔でメールスロットを監視
- メールスロットにログが来た場合はファイルへ出力
- 一定期間ログ出力がない場合はファイルをクローズ。スレッドの優先度(Priority)を下げてメインスレッドにCPUのスライスを多く割り当てる
- 再びログ出力が開始されると、眠っていたスレッドを起こして(優先度を上げて)高速にログ出力を行う。
こんな感じのログ設計にしてみました。
改修後は起動まで15分を切るようになり、ユーザのストレスもかなり改善できました。
PCで一番のボトルネックになりやすい部分はディスクへのIOです。近年は高速なストレージも増えてきましたが、それでもCPUに比べると低速です。高いスケーラビリティが求められる現場や、リアルタイム性、クリティカル性が重視される現場では、このIO制御が重要になってきます。特にファイルを開く処理はコストが高い処理なので、頻繁にオープンをしているシステムならログ設計を見直してみると良いかもしれません。
Log4Jもどきを作ってみる
さて、ここからは一般的な業務システムなどのログ出力の話をしてみたいと思います。
一般的なシステムのログ機能は、ある程度の要件は決まっています。
Java系であればlog4jから派生したSLF4JやLogbackを使えば何も作らなくてもログ出力を使えます。でも、せっかくなのでこのlog4jもどきのログ機能を.NET用に作ってみようと思います(もちろん言語が違ってもインターフェースの機能があればどの言語でもOKです)
まずはlog4jの主要な列挙体、インターフェース、クラスを挙げてみます。
ログレベル列挙体
- FATAL(致命的)
- ERROR(エラー)
- WARN(警告)
- INFO(情報)
- DEBUG(デバッグ)
- TRACE(トレース)
下に行くほど出力内容が詳細になり出力する情報量も増えます。
public enum LogLevel
{
Debug,
Info,
Warn,
Error,
Fatal
}
こんな感じです。TRACEは今回サンプルなので省きました。DebugやErrorはCLSに準拠していない名前ですが、今回はC#なのでとりあえずです。
Appenderインターフェースと実装クラス
Appenderは「どこに出力するか」を決定するクラスです。「文字列を出力する」動作だけあればいいのでインターフェースの定義はこんな感じにします。
public interface IAppender
{
void Write(string message);
}
では、実際にこのインターフェースを実装したクラスを作ってみます。
まずは、コンソールに出力するAppenderです。デバッグモードで実行する場合など、ファイルに出力する必要がない場合などに使用します。
public class ConsoleAppender : IAppender
{
public void Write(string message)
{
Console.WriteLine(message);
}
}
次はファイルに出力するAppenderを作ってみます。ファイルの場合はパスが必要になるので、コンストラクタでパスを指定しています。Writeする度にOpenしているので性能は良くありませんが、とりあえずサンプルなので、これでOKとしましょう。
public class FileAppender : IAppender
{
string FilePath;
public FileAppender(string filePath)
{
this.FilePath = filePath;
}
public void Write(string message)
{
using (StreamWriter sw = new StreamWriter(this.FilePath))
{
sw.WriteLine(message);
}
}
}
importや名前空間は省略しています。実際に使う場合は、ローテートさせる機能をIAppenderに持たせて制御したり、バッファリングの機能を持たせて出力回数を制御したりするといい感じに仕上がると思います。
あと、これを用意しておきましょう。NullAppenderです。Nullオブジェクトパターンのクラスとして「何も出力しないAppender」を用意しておきます。ユニットテストで動かす場合など、ログ出力の機能はOFFにしたい時があります。そんな時はNullAppenderで何もしなければ良いだけなので、意外と重宝します。
public class NullAppender : IAppender
{
public void Write(string message)
{
// 空っぽ
}
}
これでAppenderの準備はできました。次はLayoutを作ってみましょう。
Layoutインターフェースと実装クラス
Layoutは何をするかというと、ログに出力する内容を整形します。業務用のログにはタイムスタンプを付与したログがよく使われたりします。ログの種類によって書式が異なったり、タイムスタンプの有無、改行の取り扱いなど様々なレイアウトがあります。
通常、ログを出力する場合は、printf()のような「書式設定文字列」＋「可変個引数」の形式を許容していると便利です。また、ログレベルも併せて引数にしていしていると色々な場面で重宝します。
public interface ILayout
{
string FormatString(LogLevel level, string format, params object[] args);
}
こんな感じです。引数を元にログ出力する文字列を生成します。まずはシンプルなLayoutクラスを用意してみましょう。
public class SimpleLayout : ILayout
{
public string FormatString(LogLevel level, string format, params object[] args)
{
return string.Format(format, args);
}
}
String.Formatしてるだけです。ほんと芸がなくてすいません。。。次はタイムスタンプを付与するLayoutを用意してみましょう。
public class TimestampLayout : ILayout
{
public string FormatString(LogLevel level, string format, params object[] args)
{
StringBuilder sb = new StringBuilder();
sb.AppendFormat("{0:yyyy/MM/dd HH:mm:ss} ", DateTime.Now);
sb.AppendFormat(format, args);
return sb.ToString();
}
}
今回はLayoutは2つだけしか用意しませんでしたが、実際のシステム設計ではもっと色々な機能を実装します。メッセージIDに対応するメッセージを返却したり、プロトタイプの段階でC++の書式設定文字列を.NETの書式設定に変換してみたり、改行位置をタイムスタンプとは別の位置で揃えてみたり。
また、可変個引数はパフォーマンス面でアレなので、引数1～3個くらいのオーバーロードを用意しておくとパフォーマンス面でも安心です。
あと、バスクリンがよく使う方法として、エラーや警告のログにマークを付けたりもこのレイアウトでやったりします。運用フェーズで問い合わせがあったりした場合、一次回答までに時間制限がある場合があります。この一次回答が発生から3分以内とか、無理ゲーな時間しかない場合、いかに問題点を直感的に判断できるかが重要になります。大量に吐かれたログのgrepなんかしている暇はありません。ログレベルに応じて▲や▼、★など視覚的にログの流れを判断できるようにマーキングしておくのもレイアウトの役目です。
AppenderとLayoutを管理するLogger
主要なクラスができたので、ログ出力を行うLoggerのクラスを考えます。コンストラクタでAppenderとLayout、出力対象のログレベルを受け取り、メンバに保持しておきます。
Write()の中でログレベルの判定を行い、ログ出力するかしないかの制御をします。また、毎回ログレベルを指定するのはめんどくさいので、ラッパー関数をログレベル毎に用意しておきます。
public class Logger
{
public LogLevel Level;
public IAppender Appender;
public ILayout Layout;
public Logger(LogLevel level, ILayout layout, IAppender appender)
{
this.Level = level;
this.Layout = layout;
this.Appender = appender;
}
public void Write(LogLevel level, string format, params object[] args)
{
// 指定されたログレベルが定義済レベルより大きい場合は出力しない
if (this.Level < level) return;
this.Appender.Write(this.Layout.FormatString(level, format, args));
}
public void WriteDebug(string format, params object[] args)
{
this.Write(LogLevel.Debug, format, args);
}
public void WriteInfo(string format, params object[] args)
{
this.Write(LogLevel.Info, format, args);
}
public void WriteWarn(string format, params object[] args)
{
this.Write(LogLevel.Warn, format, args);
}
public void WriteError(string format, params object[] args)
{
this.Write(LogLevel.Error, format, args);
}
public void WriteFatal(string format, params object[] args)
{
this.Write(LogLevel.Fatal, format, args);
}
}
サンプルなのでこれくらいの機能しかありませんが、実際にはパージの処理やローテートの機能などをここで実装したり、外部のクラスに移譲したりします。
ハードコーディングは嫌なのでファクトリーを作る
コンストラクタで毎回AppenderやLayoutを渡すのは依存関係があるので、Factoryを用意して設定文字列からLoggerのインスタンスを返却するようにします。
生成文字列書式：level, layout, appender[, filePath]
level : ”debug” / ”info” / ”warn” / ”error” / ”fatal”(左記以外は例外)
layout : ”simple” / ”timestamp”(左記以外はsimple扱い)
appender : ”console” / ”file” / ”null”(左記以外はnull扱い）
filePath : appenderがfileの場合はパスを指定
こんな感じのFactoryになります。
public class LogFactory
{
public static Logger CreteLogger(string generateTokens)
{
string[] tokens = generateTokens.Split(new char[]{ ',' }, StringSplitOptions.RemoveEmptyEntries);
LogLevel level = ToLogLevel(tokens[0]);
ILayout layout = createLayout(tokens[1]);
IAppender appender = null;
if (tokens.Length == 3) appender = createAppender(tokens[2]);
if (tokens.Length == 4) appender = createAppender(tokens[2], tokens[3]);
if (appender != null) return new Logger(level, layout, appender);
throw new ArgumentException("生成文字列が不正です");
}
private static LogLevel ToLogLevel(string logLevelToken)
{
string lv = logLevelToken.ToLower().Trim();
if (lv == "debug") return LogLevel.Debug;
if (lv == "info") return LogLevel.Info;
if (lv == "warn") return LogLevel.Warn;
if (lv == "error") return LogLevel.Error;
if (lv == "fatal") return LogLevel.Fatal;
throw new ArgumentException("LogLevelの指定が間違っています");
}
private static ILayout createLayout(string layoutToken)
{
string lo = layoutToken.ToLower().Trim();
if (lo == "timestamp") return new TimestampLayout();
return new SimpleLayout();
}
private static IAppender createAppender(string appenderToken, params string[] optionToken)
{
string ap = appenderToken.ToLower().Trim();
if (ap == "console") return new ConsoleAppender();
if (ap == "file") return new FileAppender(optionToken[0]);
return new NullAppender();
}
}
実際に使う場合は
Logger logger = LogFactory.CreteLogger("debug, timestamp, console");
logger.WriteDebug("hoge");
こんな感じになります。Factoryに渡す文字列は、設定ファイルやDBに外出ししておけばコンパイルすることなく自由にAppenderやLayoutを変更できます。本番用のプロジェクト設定はファイルに出力して、ユニットテストプロジェクトの設定はNullAppenderで何も出力しない。デバッグモードでトレースしたい場合はタイムスタンプ無しのシンプルなログをコンソールに出力。シーンに合わせてログの形を変えて開発・運用して楽しい開発をしてみましょう。
最後に
簡単なサンプルプログラムでしたが、システムから不要な依存性を外部に出してしまって柔軟なログ出力が実現できるようになりました。 仕様変更や拡張性も十分あるので簡単なログ出力としてライブラリにしておけば使い回しできると思います。
メルマガではコードが書けなかったんですが、ブログになって載せることができるようになったので、また何か面白いネタがあれば書いてみようと思います。
