BoostDraftでのC#アプリケーションのパフォーマンスチューニングの事例を、数回の記事に分けて紹介していきます。

本記事におけるパフォーマンスチューニングの対象は、通常10秒以内に終わると期待されている処理が5, 6倍以上かかっているような「遅すぎる」処理です。0.1秒以下でのカリカリのチューニングは本記事では対象外です。また、普段の仕事の片手間にやっているのでパフォーマンスモニタリング等は実施していません。

弊社の製品紹介

まず初めに前提として、チューニング対象のアプリケーションについて説明します。

弊社が提供する『BoostDraft』は、ソフトウェアエンジニアが普段使っているIDEのコンセプトを法律文書に適用した、法律専門家向けの総合文書エディタです。Wordのアドインツールとして提供しており、編集したいWordファイルを読み込むと、文書中にハイライトが表示されます。ハイライトされた語句にカーソルを合わせると各条項の内容や、「定義語」と呼ばれる語彙の意味などをポップアップ表示してくれます（他にも多種多様な機能があります）。IDEで構文がハイライトされたり、定義元にジャンプできるのと似たようなものです。

パフォーマンスチューニングの意義

パフォーマンスチューニングの意義は、ビジネスサイドと開発者サイドの二面から考えることができます。

まず、ビジネスサイドですが遅すぎる処理はユーザのストレスになりうるという調査結果^[1]^[2]がある通り、アプリケーションのパフォーマンスはビジネス面でも重要ということがわかります。先の調査はWebアプリケーションに対してですが、弊社のアプリケーションにおいては文章が開かれてからハイライトが表示される時間（つまり、文章の初回読み込み時間）と考えることができます。この時間があまりにも遅いと、ユーザにとってはストレスになることは想像に容易いです^[3]。

開発者サイドでは、開発やデバッグ、CIを含むテストの時間に関わってきます。これらは何十回、何百回も行われることとなり、例えば30秒遅くなったとすると1人当たり 30 * 100 = 3000秒 = 50分 これが20人になると約16時間の損失につながるわけです。開発者は通常はデバッグビルドを使っているのでリリースビルドユーザサイドよりもさらに遅くなります。また、ユーザと同様に開発者の体験も悪くなります。

これらから、遅すぎる処理のパフォーマンスチューニングは重要であるといえます。

使用するツール

本記事ではJetBrains社のdotTraceを使用しますが、Visual Studioのプロファイラでも同じような流れでボトルネックを発見できるかと思います。本記事ではこれらのツールの具体的な使用方法は解説しません。

事例紹介

では弊社で起こった事例を紹介します。ある日開発をしていたら、あるドキュメント（以下ドキュメントA）の読み込みが異常に遅いこと（デバッグビルドで約45秒）に気が付きました。プロファイルを取るだけならすぐにできるので早速取ってみました。

上記の図では各スレッドの状態が可視化されています。dotTraceにおけるスレッドの状態は実行中（図中青）、待機中（図中灰色）、準備完了の3種です。
赤枠で囲んだスレッドの状態を見てみましょう。このスレッドは35秒近くアクティブ状態になっています。このスレッドを選択すると実行される具体的なメソッドがわかります。この場合では文書の解析処理に時間がかかっていることがわかりました。このスレッドの処理の後に初めてハイライトが表示され、ドキュメントの読み込みが完了した状態になります。

プロファイラではメソッドの実行時間がツリー構造でわかるようになっているので、どのメソッド呼び出しがどのくらい時間がかかっているかが根本的にわかります。今回の事例では get_Text （Textプロパティのgetter）から呼ばれる String.Concat が32秒もかかっていることがわかりました。

メソッドを特定できたので早速ソースコードを見てみましょう。

public List<string> Values;

public string Text
{
    get
    {
        string result = "";
        for (int i = 0; i < Values.Count; i++)
        {
            result += Values[i]; // Values[i]に対してのテキスト処理
        }
        return result;
    }
}

このコードは公開用に改変しているのですが大体こんな感じです。さて、C#に詳しい方なら何がまずいかわかるでしょう。Stringに対する += はコンパイル時に String.Concat の呼び出しに置き換えられます。String.Concat は呼び出し毎に結合後の文字列の領域をアロケーションするので Valuesの要素分だけアロケーションが発生することになります。

String.Concatをさらに詳しく見ると [GC Wait] が支配的になっていることからも、それがわかります。ではなぜ、アロケーションなのにGCが支配的になっているのか? これについては推測になってしまうので補足で説明します。

この問題に対する解決法は StringBuffer を使うことです。 StringBuffer も同様に文字列の追加時にアロケーションをするのですが、バッファのサイズが2倍になるように確保するので追加回数が多い場合にはアロケーションの回数は減ります。

public string Text
{
    get
    {
        StringBuffer result = new();
        for (int i = 0; i < Values.Count; i++)
        {
            result.append(Values[i]); // Values[i]に対してのテキスト処理
        }
        return result.ToString();
    }
}

さらに、Values は不変なのでキャッシュ変数を導入して作業は完了です。

private string _textCache = null;
public string Text
{
    get
    {
        if (_textCache is not null)
        {
            return _textCache;
        }

        StringBuilder result = new();
        for (int i = 0; i < Values.Count; i++)
        {
            result.append(Values[i]); // Values[i]に対してのテキスト処理
        }

        _textCache = result.ToString();
        return _textCache;
    }
}

修正後のパフォーマンスを測定してみましょう。

処理時間が32103msから169msとなり、約190倍速くなりました 🎉

補足: なぜ `String.Concat` でGCが長時間動くのか

Visual Studioのプロファイラ^[4]ではGCを含む様々なイベント(ETW)を取得することができます。GCのイベントは例えば、GCが起動したことやファイナライザが実行されるといった事象です^[5]。ここではGCが起動した、というイベントを取得します。

方法は上記メニューバーの「デバッグ」から「パフォーマンスプロファイラ」を開き、「.NETオブジェクト割り当て追跡」を有効にして実行するだけです。注意点としては他のツールが有効になっている場合はチェックできないので、他のツールはすべて無効にしてください。

収集結果の「コレクション」を見ると、GCのイベント一覧を見ることができます。ここで注目したいのが「GC Reason」と「Pause Duration」です。「GC Reason」はGCが開始されることとなった理由を表しており、例えば AllocLarge や AllocSmall などがあります。「Pause Duration」はGCによってスレッドがブロッキングされている時間を表しています^[6]。

AllocLarge は大きなオブジェクト、具体的には85000バイト以上のオブジェクト^[7]が、100KB割り当てられるごとに^[8]トリガーされます。
例えば、90KBくらいの大きなオブジェクトを1つ割り当てた時は100KB未満なので何も起きず、もう1つ大きなオブジェクトを割り当てた時に100KBを超えるので、AllocLargeがトリガーされます。

問題のプログラムの result の文字列長を考えると、 Values.Length * Valuesの各要素の平均長 * 2 (charのバイト数) = 1000 * 50 * 2 = 100K で約100KBとなります。resultは累積されていくので最初のほうは小さいオブジェクトですが、大きなオブジェクトの閾値を超えてしまうと、100KBごとのトリガーが高頻度で発生してしまうことになります。

「Pause Duration」を見ると大体80msかかっていることから、これが高頻度で発生すると問題のメソッドの実行時間が長くなってしまうというのが推測した理由です。

おわりに

弊社におけるパフォーマンスチューニングの事例を紹介しました。今回はかなり単純な例でしたが、次回からは少し込み入ったり工夫が必要な事例を紹介していきます。

GCについては補足ですが、本文よりも時間をかけて調べてしまいました。おかげで.NETランタイムのGCについて少しは詳しくなれた気がします。

参考

https://learn.microsoft.com/ja-jp/dotnet/standard/garbage-collection/fundamentals
https://notnullvariable.com/2024/dot-net-garbage-collection/
https://github.com/Maoni0/mem-doc/blob/master/doc/.NETMemoryPerformanceAnalysis.md
- GCについて事細かに書かれています。時間があるときに読みたい。

脚注

https://www.thinkwithgoogle.com/consumer-insights/consumer-trends/mobile-site-load-time-statistics/ ↩︎
https://www.biglobe.co.jp/pressroom/info/2024/04/240409-1 ↩︎
実際のところは、弊社の製品がWordのアドインで提供されている関係上、ユーザ目線ではWord自体の操作や文書の読み込みに支障がなければ、大きな損害にはならないと考えることができます。そのような事情もあり、できるだけWordのメインスレッドをブロックしないような設計にしつつ、それでもブロックしてしまうケースを中心にパフォーマンスチューニングをしています。 ↩︎
残念ながらdotTraceやdotMemoryではGCのイベントを取得することができなかったので、Visual Studioを使いました。 ↩︎
https://learn.microsoft.com/en-us/dotnet/framework/performance/garbage-collection-etw-events ↩︎
https://learn.microsoft.com/en-us/visualstudio/profiling/dotnet-alloc-tool?view=vs-2022 ↩︎
https://github.com/Maoni0/mem-doc/blob/master/doc/.NETMemoryPerformanceAnalysis.md#loh-large-object-heap ↩︎
https://github.com/Maoni0/mem-doc/blob/master/doc/.NETMemoryPerformanceAnalysis.md#measure-allocations ↩︎

Discussion