asyncの落とし穴Part2, SynchronizationContextの向こう側

非同期QUIZの時間がやってきました！前回はデッドロックについてでしたが、今回はヌルポについて扱いましょう。まずは以下のコードの何が問題なのかを当ててください。ASP.NET MVCです。あ、.NET 4.5ね。

public class HomeController : Controller
{
    async Task DoAsync()
    {
        await Task.Delay(TimeSpan.FromSeconds(3));
    }

    public ActionResult Index()
    {
        DoAsync();
        return View();
    }
}

どこがダメで、どうすれば改善されるのかはすぐ分かると思います。「なにが起こるのか」「なぜ起こるのか」について、考えてみてください。おわり。

さて、で、Ctrl+F5で実行すると、このコードは何の問題もなくふとぅーに動きます。一見何の問題もない。実際何の問題もない。オシマイ。

というのもアレなので、何が起こっているのか観測します。まず、Global.asax.csに以下のコードを。

protected void Application_Start()
{
    // ルーターの登録とか標準のものがこの辺に

    Trace.Listeners.Add(new TextWriterTraceListener(@"D:\log.txt"));
    Trace.AutoFlush = true;

    System.Threading.Tasks.TaskScheduler.UnobservedTaskException += (sender, e) =>
    {
        Trace.WriteLine(e.Exception);
    };
}

で、本体はこんな風に。

public class HomeController : Controller
{
    async Task DoAsync()
    {
        Trace.WriteLine("start"); // 何か開始処理があるのだとする

        await Task.Delay(TimeSpan.FromSeconds(3)); // 何か非同期処理してるとする

        Trace.WriteLine("end"); // 何か後処理があるのだとする
    }

    public ActionResult Index()
    {
        GC.Collect(); // GC自然発生待ちダルいので発動しちゃう

        var _ = DoAsync(); // 非同期処理を"待たない"
        return View();
    }
}

D:\log.txtは、まぁどこに吐いてもいいんですが、ちゃんと書き込み権限があるところに。んでは、実行しましょう。log.txtは、初回はまず、「start」と書かれます。つまり、endまで到達してないことが確認できます。二回目のアクセスではGC.Collectが走り、それによりUnobservedTaskExceptionが実行されます。で、log.txtには以下のものが書き込まれます。

System.AggregateException: タスクの例外が、タスクの待機によっても、タスクの Exception プロパティへのアクセスによっても監視されませんでした。その結果、監視されていない例外がファイナライザー スレッドによって再スローされました。 ---> System.NullReferenceException: オブジェクト参照がオブジェクト インスタンスに設定されていません。
   場所 System.Web.ThreadContext.AssociateWithCurrentThread(Boolean setImpersonationContext)
   場所 System.Web.HttpApplication.OnThreadEnterPrivate(Boolean setImpersonationContext)
   場所 System.Web.HttpApplication.System.Web.Util.ISyncContext.Enter()
   場所 System.Web.Util.SynchronizationHelper.SafeWrapCallback(Action action)
   場所 System.Web.Util.SynchronizationHelper.<>c__DisplayClass9.<QueueAsynchronous>b__7(Task _)
   場所 System.Threading.Tasks.ContinuationTaskFromTask.InnerInvoke()
   場所 System.Threading.Tasks.Task.Execute()
   --- 内部例外スタック トレースの終わり ---
---> (内部例外 #0) System.NullReferenceException: オブジェクト参照がオブジェクト インスタンスに設定されていません。
   場所 System.Web.ThreadContext.AssociateWithCurrentThread(Boolean setImpersonationContext)
   場所 System.Web.HttpApplication.OnThreadEnterPrivate(Boolean setImpersonationContext)
   場所 System.Web.HttpApplication.System.Web.Util.ISyncContext.Enter()
   場所 System.Web.Util.SynchronizationHelper.SafeWrapCallback(Action action)
   場所 System.Web.Util.SynchronizationHelper.<>c__DisplayClass9.<QueueAsynchronous>b__7(Task _)
   場所 System.Threading.Tasks.ContinuationTaskFromTask.InnerInvoke()
   場所 System.Threading.Tasks.Task.Execute()<---

おぅ！例外が発生していた！ぬるり！ぬるり！

GC.Collectを実行している理由は、Taskに溜まった未処理例外は、GCが走ったタイミングでUnobservedTaskExceptionに渡されるので、それを待つ時間を短縮しているだけです。GC.Collectを明示的に実行しなくても、長く動かしてればそのうち発生します。

というわけで、何が起こるのか、というと、await Task.Delayのところでヌルリが発生します。↑の例外情報からは、どこで発生していたのかの情報が一切出てこないので(さすがにこれなんとかして欲しいですけどねぇ……)、いざ発生するとなると場所を突き止めるのに割と苦労します、というか虱潰ししかないので結構大変です。そもそもUnobservedTaskExceptionをモニタしてなければ、発生していたことにすら気づけません。

なぜ起こるのか、というと、awaitによってPOSTする先のContextが消滅しているからです。非同期処理を待たなかったことによって、Viewの表示まで全て完了してContextが消滅する。その後で、DoAsync内のawaitが完了し、続行しようとPOSTを開始する、と、しかしContextは消滅していてなにもなーい。ので、ぬるり。

では、解決方法は、というと、例によってasyncで統一するか

public class HomeController : Controller
{
    async Task DoAsync()
    {
        Trace.WriteLine("start"); // 何か開始処理があるのだとする

        await Task.Delay(TimeSpan.FromSeconds(3)); // 何か非同期処理してるとする

        Trace.WriteLine("end"); // 何か後処理があるのだとする
    }

    public async Task<ActionResult> Index()
    {
        GC.Collect();

        await DoAsync(); // awaitする
        return View();
    }
}

もしくはConfigureAwait(false)でContextを維持しないこと。

public class HomeController : Controller
{
    async Task DoAsync()
    {
        Trace.WriteLine("start"); // 何か開始処理があるのだとする

        await Task.Delay(TimeSpan.FromSeconds(3)).ConfigureAwait(false); // ConfigureAwait(false)する

        Trace.WriteLine("end"); // 何か後処理があるのだとする
    }

    public ActionResult Index()
    {
        GC.Collect();

        var _ = DoAsync(); // 非同期処理を"待たない"
        return View();
    }
}

です。

そもそも、何故非同期処理を"待たない"のか。例えば、アクセスログを取るために記録するだけだとか、別に完了を待つ必要がないものだったりするなら、待たないことでレスポンスは速くなる。待つ必要ないのなら、待たなくてもいいぢゃない。それはそうです。

なので、待たないなら待たないでいいのですが、中身について用心しないと、ヌルりで死んでしまいます。これは、同期的に待つ時もそうですね。待つなら待つでいいですけれど、中身について用心しないと、デッドロックで死んでしまいます。待っても死亡、待たなくても死亡、ホント非同期は地獄だぜ！

まあ、変数で受けたりしない限りは警告は出してくれますので（ウザいと思っていたアナタ！実に有益な警告ではないですか！）、不注意による死亡はある程度は避けられはします。

.NET 4.0 vs .NET 4.5

.NET 4.5だと、↑のような挙動ですが、.NET 4.0だとちょっと事情が違ったりします。async/awaitは利用したままで、ターゲットフレームワークのバージョンだけ4.0にしましょう。

<system.web>
    <httpRuntime targetFramework="4.0" />
    <compilation debug="true" targetFramework="4.0" />
</system.web>

で、Ctrl+F5で実行して、何度かブラウザをリロードしましょう。死んでます。IIS Expressが。完全に無反応になります。何故？Windowsのイベントビューアーを見ましょう。

ハンドルされない例外のため、プロセスが中止されました。というわけで、未処理例外が突き抜けてアプリケーションエラーとして記録されていくためです。プロダクション環境でもIISのラピッドフェール保護が発動して、デフォルトでは5分以内に5エラーでアプリケーションは停止します。これは実にクリティカル。

なんで.NET 4.0と4.5で挙動が違うのか、というと、Taskの未処理例外の扱いが4.0と4.5で変わったためです。この辺はPfxTeamのTask Exception Handling in .NET 4.5を参照にどーぞ。4.5のほうが安全っちゃー安全ですね。いずれにせよ、UnobservedTaskExceptionの例外ロギングは欠かさずやっておきましょう。

まとめ

非同期もいいんですけど、実際にマジでフルに使い出すと結構なんだかんだでハマりどころは多いですねぇ。幸い、デバッガビリティに関してはWindows 8.1 + Visual Studio 2013である程度改善するようで、待ち遠しいです。とはいえデッドロックだったりコンテキスト場外でヌルりだとかは、注意するしかない。

ASP.NET MVCのフィルターはやく非同期に対応してくださいー。ASP.NET MVC 5でも予定に入ってないようでどうなってんだゴルァ。Resultで待つしかなくて非常にヒヤヒヤします。EF6も非同期対応とか、そもそもMVC 5では.NET 4.5からのみだとか、どんどん非同期使われてくにつれ、死亡率も間違いなく上がってきますにゃ。