C# Tips | ログ・例外・診断：パフォーマンス計測

C# C#
スポンサーリンク

はじめに：パフォーマンス計測は「コードの速さを“感覚”ではなく“数字”で語るための道具」

業務システムを書いていると、必ずこういう会話が出てきます。

「この処理、なんか遅くない？」
「どれくらい遅いんだっけ？」
「前より速くなったって言える根拠ある？」

ここで「体感的に速くなった気がする」では、説得力が弱いんですよね。
だからこそ パフォーマンス計測 が必要になります。

パフォーマンス計測の本質は、

「処理にかかった時間を、ミリ秒や秒といった“数字”で記録し、
どこがボトルネックか、改善でどれだけ良くなったかを、客観的に語れるようにする」

ことです。

ここでは、初心者向けに

Stopwatch を使った基本的な計測
「区間ごとに計測する」考え方
ログと組み合わせたパフォーマンス計測ユーティリティ
非同期処理の計測

を、例題付きでかみ砕いて説明します。

パフォーマンス計測の基本：Stopwatch を使う

「スタートして、終わったら止めて、経過時間を見る」

C# でパフォーマンス計測をするときの基本ツールが System.Diagnostics.Stopwatch です。
ストップウォッチという名前の通り、「開始」「停止」「経過時間の取得」ができます。

一番シンプルな例から見てみましょう。

using System.Diagnostics;

public void DoWork()
{
    var sw = Stopwatch.StartNew();  // 計測開始

    // 計測したい処理
    HeavyWork();

    sw.Stop();                      // 計測終了

    Console.WriteLine($"HeavyWork にかかった時間: {sw.ElapsedMilliseconds} ms");
}
C#

Stopwatch.StartNew() は「インスタンスを作ってすぐ計測開始」してくれる便利メソッドです。
処理が終わったら Stop() を呼び、ElapsedMilliseconds や Elapsed（TimeSpan）で経過時間を取り出します。

ここでの重要ポイントは、

「パフォーマンス計測は“処理の前後を挟む”だけで始められる」
「まずは“どれくらいかかっているか”を知ることがスタートライン」

ということです。
最初から難しいことを考えなくてよくて、「とりあえず Stopwatch で測ってみる」が正解です。

区間ごとに計測する：どこが遅いかを切り分ける

「処理全体」だけでなく「中のステップ」を測る

「このメソッドが遅い」ということが分かったら、次に知りたいのは「どの部分が遅いのか」です。
そこで効いてくるのが「区間ごとの計測」です。

例えば、ユーザー登録処理を考えてみます。

public void RegisterUser(UserRequest request)
{
    var sw = Stopwatch.StartNew();

    Validate(request);          // 入力チェック
    var user = MapToEntity(request); // マッピング
    SaveToDatabase(user);       // DB 保存

    sw.Stop();
    Console.WriteLine($"RegisterUser 全体: {sw.ElapsedMilliseconds} ms");
}
C#

これだと「全体の時間」は分かりますが、「どこが遅いか」は分かりません。
そこで、区間ごとに計測します。

public void RegisterUser(UserRequest request)
{
    var total = Stopwatch.StartNew();

    var swValidate = Stopwatch.StartNew();
    Validate(request);
    swValidate.Stop();

    var swMap = Stopwatch.StartNew();
    var user = MapToEntity(request);
    swMap.Stop();

    var swSave = Stopwatch.StartNew();
    SaveToDatabase(user);
    swSave.Stop();

    total.Stop();

    Console.WriteLine($"RegisterUser 全体: {total.ElapsedMilliseconds} ms");
    Console.WriteLine($"  Validate: {swValidate.ElapsedMilliseconds} ms");
    Console.WriteLine($"  MapToEntity: {swMap.ElapsedMilliseconds} ms");
    Console.WriteLine($"  SaveToDatabase: {swSave.ElapsedMilliseconds} ms");
}
C#

これで、「DB 保存が 90% の時間を食っている」といったことが分かるようになります。

ここでの重要ポイントは、

「パフォーマンス計測は“どこが遅いかを切り分ける”ために使う」
「全体だけでなく、ステップごとに測ることで、改善の優先順位が見えてくる」

ということです。

ログと組み合わせたパフォーマンス計測ユーティリティ

「計測結果をログに残して、後から分析できるようにする」

コンソールに出すだけだと、その場限りで終わってしまいます。
業務システムでは、ログにパフォーマンス情報を残しておくと、後から「どの処理が重いか」を分析できて便利です。

ILogger と組み合わせた小さなユーティリティを作ってみます。

using System.Diagnostics;
using Microsoft.Extensions.Logging;

public static class PerfLogger
{
    public static void Measure(string name, Action action, ILogger logger)
    {
        var sw = Stopwatch.StartNew();

        action();

        sw.Stop();

        logger.LogInformation(
            "Perf: {Name} Elapsed={Elapsed} ms",
            name,
            sw.ElapsedMilliseconds);
    }

    public static T Measure<T>(string name, Func<T> func, ILogger logger)
    {
        var sw = Stopwatch.StartNew();

        var result = func();

        sw.Stop();

        logger.LogInformation(
            "Perf: {Name} Elapsed={Elapsed} ms",
            name,
            sw.ElapsedMilliseconds);

        return result;
    }
}
C#

使い方の例です。

PerfLogger.Measure("RegisterUser", () => RegisterUser(request), _logger);

var user = PerfLogger.Measure("LoadUser", () => LoadUser(id), _logger);
C#

ログには、例えばこんな行が残ります。

「Perf: RegisterUser Elapsed=123 ms」
「Perf: LoadUser Elapsed=45 ms」

ここでの重要ポイントは、

「パフォーマンス計測をユーティリティに閉じ込めることで、
“測る”という行為を簡単に、かつ一貫したフォーマットで行えるようにする」

ということです。
ログ分析ツールと組み合わせれば、「RegisterUser の平均時間」「最大時間」なども簡単に集計できます。

非同期処理のパフォーマンス計測

async/await でも考え方は同じ

今どきのコードは async が多いので、非同期版のパフォーマンス計測も用意しておくと便利です。

public static class PerfLoggerAsync
{
    public static async Task MeasureAsync(
        string name,
        Func<Task> action,
        ILogger logger)
    {
        var sw = Stopwatch.StartNew();

        await action();

        sw.Stop();

        logger.LogInformation(
            "Perf: {Name} Elapsed={Elapsed} ms",
            name,
            sw.ElapsedMilliseconds);
    }

    public static async Task<T> MeasureAsync<T>(
        string name,
        Func<Task<T>> func,
        ILogger logger)
    {
        var sw = Stopwatch.StartNew();

        var result = await func();

        sw.Stop();

        logger.LogInformation(
            "Perf: {Name} Elapsed={Elapsed} ms",
            name,
            sw.ElapsedMilliseconds);

        return result;
    }
}
C#

使い方の例です。

await PerfLoggerAsync.MeasureAsync(
    "CallExternalApi",
    async () => await CallExternalApiAsync(),
    _logger);

var user = await PerfLoggerAsync.MeasureAsync(
    "LoadUserFromApi",
    async () => await LoadUserFromApiAsync(id),
    _logger);
C#

ここでの重要ポイントは、

「非同期でも“前後を挟む”だけで計測できる」
「同期版と非同期版で同じフォーマット・同じルールを使うと、ログが見やすくなる」

ということです。

実務での使いどころと注意点

「常にオン」ではなく「必要なときにオンにする」

パフォーマンス計測は便利ですが、やりすぎるとそれ自体が負荷になることがあります。
特に、全リクエスト・全メソッドに対してミリ秒単位のログを取り続けると、ログ量が膨大になり、
ログ書き込みがボトルネックになることもあります。

そこで大事なのは、「どこで計測するか」を選ぶことです。

明らかに重そうな処理（外部 API、DB 集約、バッチ処理など）
ユーザーから「遅い」と言われている画面
最近改修したばかりで、パフォーマンスが気になる箇所

こういったところに絞って計測し、
問題が解決したら「常時オン」から「必要なときだけオン」に切り替える、という運用もよくあります。

ここでの重要ポイントは、

「パフォーマンス計測は“スポットライト”のように使う」
「常に全体を照らすのではなく、気になるところに当てて、終わったら少し絞る」

という感覚です。

まとめ：パフォーマンス計測は“感覚を数字に変える”ためのユーティリティ

パフォーマンス計測の本質を一言で言うと、

「処理の速さ・遅さを、
“なんとなく”ではなく、
ミリ秒という数字で語れるようにする」

ことです。

押さえておきたいポイントを整理すると、

Stopwatch で処理の前後を挟めば、すぐに時間を測れる。
全体だけでなく、ステップごとに計測することで、どこがボトルネックかが見えてくる。
ILogger と組み合わせたパフォーマンス計測ユーティリティを作ると、ログに一貫した形で残せる。
非同期処理でも同じ考え方で計測できるように、MeasureAsync 形を用意しておくと便利。
計測は「気になるところにスポットライトを当てる」イメージで使い、やりすぎて自分で自分を重くしない。

ここまで腹落ちしていれば、「なんか遅い気がする」から一歩進んで、
“数字で語れるパフォーマンス改善”に踏み出せるようになります。

スポンサーリンク
タイトルとURLをコピーしました