はじめに
言いたいことはタイトルに書いたことがすべてなんですが、もう少し深く掘り下げてみようかと思います。どうしてかというと、このせいでデッドロックを起こしたり動作が極めて遅いアプリが結構あるんですけど、原因に気づかずにOSやクラウドに原因を求めるケースを散見するからです。
一番単純なケース
ここ から一部を抜き出して、少々書き換えて本質部分だけを以下に示します。
using Microsoft.AspNetCore.Mvc;
namespace BuggyDemoWeb.Controllers;
[ApiController]
[Route("[controller]")]
public class BadController : ControllerBase
{
[HttpGet]
public IActionResult SyncOverAsync()
{
string val = DoAsync().Result;
return Ok(val);
}
private async Task<string> DoAsync()
{
var random = new Random();
await Task.Delay(random.Next(10) * 100);
return Guid.NewGuid().ToString();
}
}
これだけの単純なコードでも問題が起きます。クラウドにデプロイして/badへ多数のHTTP GETリクエストを投げ続けると、結構な確率でレスポンスが悪化します。厄介なのは、ローカル環境で軽くテストしただけでは問題が起きにくいことです。「今時こんなコード書くやついるか？」と思う人もいるかも知れませんが、現実に沢山あります。たとえばこんな場合です：
- 古いライブラリをそのまま使い続けている（ライブラリの詳細な実装は不明。様々な理由により変更できない）
- コンストラクタ内でasyncなメソッドを呼び出している
- 単純に「問題ないだろう」と実装者が思っている。だってローカルで問題なく動いたし
実際にあったケース
現実には（当然ですが）もっと複雑なケースで発生します。たとえばこういうコードです。サンプル用に初期化等は簡略化してあります。
using Microsoft.AspNetCore.Mvc;
namespace AsyncSyncMixedSample.Controllers;
[ApiController]
[Route("[controller]")]
public class Bad2Controller : ControllerBase
{
private const string ConnectionString = ".....";
[HttpGet]
public IEnumerable<string> BadGet()
{
var results = RetryHelper.Retry<List<string>>(() =>
{
using var sql = new SqlHelper(ConnectionString);
var entries = sql.GetSummaries();
var output = PostProcessAsync(entries).Result;
return output.ToList();
});
return results;
}
private async Task<IEnumerable<string>> PostProcessAsync(IEnumerable<string> summaries)
{
var random = new Random();
await Task.Delay(random.Next(10) * 100);
return summaries.Reverse();
}
}
SqlHelperクラスの実装はこんな感じ
using System.Data.SqlClient;
namespace AsyncSyncMixedSample;
public class SqlHelper : IDisposable
{
private SqlConnection _connection;
public SqlHelper(string connectionString)
{
_connection = new SqlConnection(connectionString);
var connected = _connection.OpenAsync().Wait(TimeSpan.FromSeconds(5));
if (!connected)
{
throw new Exception("Connection error");
}
}
public IEnumerable<string> GetSummaries()
{
using var command = new SqlCommand("SELECT TOP 5 SUMMARY FROM SUMMARIES", _connection);
var reader = command.ExecuteReader();
var entries = new List<string>();
while (reader.Read())
{
var item = reader.GetString(0);
entries.Add(item);
}
return entries;
}
public void Dispose()
{
if (_connection != null)
{
_connection.Close();
}
}
}
RetryHelperの実装は省略します。一応簡単に説明すると、/bad2へのHTTP GETリクエストを受け取るとGetBad()が呼び出されます。GetBad()はデータベースへのアクセスをSqlHelperクラスを使って行います。SqlHelper.GetSummaries()を呼び出すとSQLクエリを発行し、得られたデータはList<string>として返されます。返されたリストをPostProcessAsync()に渡して、結果を.Resultで受け取ります。
要するに、HTTPリクエストを受け付けたContollerがデータベースへのアクセスをして、受け取った結果を加工して返しています。単純化していますが、現実にあるシナリオですね。上記はControllerから直接DBアクセスしちゃってますが、DIで登録されたServiceを呼び出すのでもまったく同様です。
このコードはローカルでの動作確認では問題が起きませんが、デプロイしてある程度の負荷をかけると結構な確率で問題が起きます。実際にやってみた結果がこれです。
上の図はレスポンスタイムの50, 90, 95パーセンタイルです。PostProcessAsync()では最大で1000msまでの遅延しか起こしていませんが、95パーセンタイルでは3000ms以上になっています。データベースへアクセスは単純なSELECTであり、ここまでのパフォーマンスの悪化の要因としては説明しにくいです。
プロセスダンプを取ってみて解析してみましょう。App ServiceのポータルメニューからDiagnose & Solve Problems > Diagnostic Tools > Collect Memory Dumpを選び、ダンプを保存するためのストレージアカウントを選択または作成し、ダンプを取るインスタンスを選択してCollect MemoryDumpをクリックすると、全自動でプロセスダンプを取って解析してくれます。便利。
しばらく待つと解析結果ファイル(DiagnosticAnalysis-<インスタンス名>)が表示されますので、その右隣のアイコンをクリックすると、解析結果が開きます。こんな感じです。
Sync over Ayncが発見されてますね。ご丁寧に悪い例まで載せてくれてます。問題のメソッド名をクリックするとスタックトレースが見られます。
Windbgを一切使わずにここまで全部やってくれるの便利だと思いませんか。もちろんダンプファイルはダウンロードできますので、手元のwindbgでも同様の結果を得ることができます。
Exampleの下にはDavid Fowlerのgithubリポジトリへのリンクが付いていて、「どうしてやってはいけないのか」の詳細が解説されてます。
まとめ
- Asyncするなら徹底的にやらないと危険。特によくわからず使ってるライブラリ、恐いですよ。
- 「ローカルで動いてるからOK」「クラウドでしか問題が起きないんだからクラウドのせいだ」は常に真ではありませぬ。
- ダンプ解析は強力。パケットキャプチャと合わせればもっと強力。その手間を軽減させるためのツールがApp Serviceから提供されてます。