ログを減らすだけで処理速度が50%改善？ログとパフォーマンスの関係

はじめに

バックエンド開発において、適切なログを追加することは、トレーサビリティのために非常に重要です。処理がいつ開始され、いつ終了したのかを示すログを追加することは良い習慣です。また、何か問題が発生した場合に、どの部分のコードで失敗したのかを把握できるように、処理の途中にもログを追加することがよくあります。

しかし、ログ出力は無料ではありません。パフォーマンスの面ではそれほど大きな負荷ではないかもしれませんが、それでもコストは発生します。大規模な企業向けに開発する場合は、ログ出力であっても、パフォーマンスを考慮しながら慎重に行う必要があります。

どのような影響があるだろうか？

これは、以前参加していたプロジェクトでの話です。C#を使って、毎日深夜にデータベースを更新するバッチ処理を作っていました。処理は毎日実行されるはずでしたが、完了するまでに約18時間かかり、通常の業務利用にも支障が出ていました。もちろん、最初にインデックスを追加したり、SQLクエリを改善したりするなど、データベースの最適化を試みましたが、どれも大きな効果はありませんでした。

なぜ処理がこれほど遅いのかをデバッグしている中で、あまりにも多くのことをログに出力しており、1回の実行分のログをすべて確認することが不可能な状態になっていることに気づきました。エラー以外のログをすべて無効にしたところ、突然、処理が1時間未満で完了するようになりました。こうして、ログの出しすぎがボトルネックになっていたことがわかりました。

もちろん、エラー以外のログがない状態でバッチを運用し続けることはできませんでしたが、必要最低限のログだけを有効にした後でも、約50%の改善が見られました。

なぜ影響を与えるのか？

問題は、すべてのログ出力を、フォーマット処理を行った後にConsole.WriteLineを呼び出すクラスを通して行っていたことです。Console.WriteLineは同期処理なので、バッチを実行しているスレッドは、出力処理が完了するまで待ってから処理を続ける必要があります。次に進む前にWriteLineによるコンソールへの出力が完了するまで待つ必要がありました。

また、ログを出力しすぎていました。データベースを呼び出すたびに、使用したSQLコマンドなども出力していました。ログを出しすぎていたため、処理が常に停止してログの出力が終わるのを待つ状態になり、全体の処理速度が低下していました。

どうすればいいですか？

ログはデバッグに非常に役立つツールであり、ログがまったく出力されないバッチ処理では、処理が実行されているのかどうかを確認することが難しくなります。しかし、何をログに出力し、何を出力しないかを少し選別することが役立ちます。適切な処理を設計するためには、バランスを取ることが重要です。

今回の場合、問題の一つはログ出力用のライブラリを使用しておらず、すべてのログ出力を処理の他の部分と同じスレッドで行っていたことです。可能であれば、NLogのような専用のライブラリを使用することをおすすめします。これらのライブラリには非同期ログ出力などの機能があり、ログ出力によってアプリケーションの処理が不必要にブロックされるのを防ぐのに役立ちます。ライブラリを使えない、または使いたくない場合でも、少なくともログ出力の処理を専用のスレッドで行うようにしましょう。そうすることで、処理の他の部分がブロックされるのを避けることができます。