事象概要

土曜日の朝から継続的にサーバーの高CPU使用率に関するアラートが通知され、午後には累計30件以上のアラートが確認されました。クラウドモニタリングのコンソールを確認すると、CPU使用率が常に高い状態にあることがわかりました。

プロセスを特定したところ、.NET Framework 4.0で動作するCARシステムが原因であることが判明しました。

調査プロセス

CPU使用率が50%を超えた場合に3秒間待機し、2回のダンプを取得するコマンドを実行しました。プロセスIDは6100です。

procdump -ma -c 50 -s 3 -n 2 6100

初回実行時、管理者権限でCMDを起動していなかったためエラーが発生しました。管理者として実行し直すことで問題なくダンプを取得できました。

取得したダンプファイルをローカル環境にダウンロードし、WinDbgで解析を開始しました。

# SOSとCLRのロード
0:016> .load C:\Windows\Microsoft.NET\Framework\v4.0.30319\sos.dll
0:016> .load C:\Windows\Microsoft.NET\Framework\v4.0.30319\clr.dll

0:062> !runaway
 User Mode Time
  Thread       Time
  16:dc4       0 days 0:13:12.593
  15:2be4      0 days 0:13:06.390
  17:2404      0 days 0:13:06.328
  18:bb4       0 days 0:12:45.953

!runawayコマンドにより、上位のスレッドが異常に長い時間実行されていることが確認されました。16番スレッドに切り替えて詳細を確認します。

0:016> ~16s
0:016> !clrstack
OS Thread Id: 0xdc4 (16)
Unable to walk the managed stack. The current thread is likely not a 
managed thread. You can run !threads to get a list of managed threads in
the process

マネージドスレッドとして認識されないため、サーバーから正しいバージョンのsos.dllとclr.dllを取得して再ロードしました。

0:018> .load D:\debug\sos.dll
0:018> .load D:\debug\clr.dll

全スレッドのマネージドスタックを確認したところ、GCの発生が頻繁に観察されました。さらに!dumpstackを実行した結果、Volcker.Autotrader.ProductPropertieData.GetAll()メソッドが複数のスレッドで繰り返し実行されていることが判明しました。

問題の特定

該当メソッドのソースコードを確認するため、モジュールをエクスポートしました。

0:053> !ip2md 1c15f4bd
MethodDesc:   1b9ec174
Method Name:  Volcker.Autotrader.ProductPropertieData.GetAll()
Class:        1bd668a4
MethodTable:  1b9ec19c
mdToken:      06000088
Module:       1b9ebbd4

0:053> !savemodule 1b9ebbd4 D:\debug\GetAll.dll

メソッドの実装を確認したところ、リフレクションを多用したデータマッピング処理が行われていました。

virtual public void PopulateFromReader(MethodBase method, Object target, IDataReader dataReader)
{
    var columnCache = new Dictionary();
    for (int index = 0; index < dataReader.FieldCount; index++)
    {
        columnCache[dataReader.GetName(index).ToLower()] = dataReader.GetValue(index);
    }
    
    var propertyMap = RetrievePropertyMappings(method, FieldType.DatabaseColumn);
    foreach (string key in propertyMap.Keys)
    {
        PropertyInfo property = (PropertyInfo)propertyMap[key];
        object value = columnCache.ContainsKey(key) ? columnCache[key] : null;
        
        if (value != null)
        {
            AssignPropertyValue(ref target, ref property, ref value);
        }
    }
}

特に以下の行でパフォーマンスのボトルネックが発生していました：

var propertyMap = RetrievePropertyMappings(method, FieldType.DatabaseColumn);

このメソッドがリフレクションを使用してプロパティ情報を毎回取得しており、クラスのプロパティ数が増えるにつれて処理時間が増加していました。

対策と実装

問題の根本原因はリフレクションの繰り返し使用によるCPU負荷でした。コードベースが古く、詳細な仕様が不明なため、大規模な改修は避け、キャッシュ機構を導入することにしました。

対象のデータは辞書テーブルであり、変更頻度が低いという特性から、24時間のキャッシュを実装しました。

private static readonly ConcurrentDictionary _propertyCache = 
    new ConcurrentDictionary();

public virtual void PopulateFromReader(MethodBase method, Object target, IDataReader dataReader)
{
    var cacheKey = method.DeclaringType.FullName;
    var properties = _propertyCache.GetOrAdd(cacheKey, _ => 
        method.DeclaringType.GetProperties(BindingFlags.Public | BindingFlags.Instance));
    
    var columnCache = new Dictionary();
    for (int index = 0; index < dataReader.FieldCount; index++)
    {
        columnCache[dataReader.GetName(index).ToLower()] = dataReader.GetValue(index);
    }
    
    foreach (var property in properties)
    {
        if (columnCache.TryGetValue(property.Name.ToLower(), out var value) && value != null)
        {
            property.SetValue(target, value);
        }
    }
}

変更をデプロイ後、CPU使用率は即座に正常値に戻りました。数日間の監視でも異常は再発していません。

学習ポイント

• リフレクションの多用はパフォーマンスに重大な影響を与える可能性がある
• キャッシュ戦略の導入は、レガシーコードの改善において効果的なアプローチとなり得る
• WinDbgとSOSの活用により、.NETアプリケーションの低レベルな問題を特定できる
• !runawayで高CPU使用スレッドを特定し、!dumpstackで呼び出しスタックを分析する手法が有効