サナギわさわさ.json

サナギさんとキルミーベイベーとプログラミングが好きです

Play2のPromiseと非同期処理について調査した

PlayFrameWorkはイベント駆動型を基本としているため、全ての処理は非同期で実行される事が前提となっています。 これによって単一スレッドで複数のリクエストを捌く事ができます。

非同期のHTTP呼び出しを実現するPlay WS APIを使って外部のWebサイトにアクセスするコードを例にして、非同期処理でクライアントからのリクエストがどう扱われるか見てみます。

非同期処理でのリクエスト挙動

非同期で外部Webサイトにアクセスするコントローラ
public class TestController extends Controller {

    public static F.Promise<Result> nonBlockingUrlAccess() {
        final String uniqueId = UUID.randomUUID().toString();
        Logger.debug("request start : " + uniqueId);

        F.Promise<WS.Response> resultPromise = WS.url("http://yahoo.co.jp").get();
        return resultPromise.map(new F.Function<WS.Response, Result>() {
            @Override
            public Result apply(WS.Response response) throws Throwable {
                Logger.debug("return result : " + uniqueId);
                return Results.ok();
            }
        });
    }
}

このコントローラに対して5箇所から同時にアクセスした場合、以下のようなログが吐かれます。

request start : 61f6a075-7b23-4547-a8f8-e108e0aa9b82
request start : 249b3fd0-80fa-4e02-9702-fc46580ff3a5
request start : c98bc9cb-9f5a-43ac-8bb4-190dab9431fe
request start : d0d79bd4-ecdd-4b31-9fc5-aa13ceb41c29
request start : 512300bc-1757-4543-9004-39362ec1fbea
return result : 249b3fd0-80fa-4e02-9702-fc46580ff3a5
return result : 512300bc-1757-4543-9004-39362ec1fbea
return result : 61f6a075-7b23-4547-a8f8-e108e0aa9b82
return result : d0d79bd4-ecdd-4b31-9fc5-aa13ceb41c29
return result : c98bc9cb-9f5a-43ac-8bb4-190dab9431fe

また、処理時間は以下のようになります。

Concurrency Level:      5
Time taken for tests:   1.033 seconds
Complete requests:      5
Failed requests:        0
Requests per second:    4.84 [#/sec] (mean)
Time per request:       1033.332 [ms] (mean)
Time per request:       206.666 [ms] (mean, across all concurrent requests)

Promiseを使って非同期に外部Webサイトにアクセスする事で、1スレッドで複数のリクエストを同時に受け付け、結果が返ってきたものから順番にレスポンスを返せている事が分かります。

このように、基本的に非同期処理を行っている限り問題は無いのですが、実際にコードを書いているとDBアクセスなどでどうしても同期処理を行わなければいけない場合があります。

という訳で同期処理を普通に行った際にクライアントからのリクエストがどう扱われるか見てみます。

同期処理でのリクエスト挙動

重い同期処理を模擬したコントローラ
public class TestController extends Controller {

    public static Result blockingHeavy() throws InterruptedException {
        final String uniqueId = UUID.randomUUID().toString();
        Logger.debug("request start : " + uniqueId);
        Thread.sleep(1000);
        Logger.debug("return result : " + uniqueId);
        return ok();
    }
}

このコントローラに対して5箇所から同時にアクセスした場合、以下のようなログが吐かれます。

request start : 5c0fb9e8-875e-4192-957a-20bc102554df
return result : 5c0fb9e8-875e-4192-957a-20bc102554df
request start : e28064e5-231b-43f5-9c44-99551e278491
return result : e28064e5-231b-43f5-9c44-99551e278491
request start : 0cf300fb-be2c-4ff0-8809-38e9ed13e725
return result : 0cf300fb-be2c-4ff0-8809-38e9ed13e725
request start : 80f5e280-6d51-438c-91da-edf94173d021
return result : 80f5e280-6d51-438c-91da-edf94173d021
request start : 167c95a5-bcd2-4501-9411-f9adf46f9874
return result : 167c95a5-bcd2-4501-9411-f9adf46f9874

また、処理時間は以下のようになります。

Concurrency Level:      5
Time taken for tests:   5.029 seconds
Complete requests:      5
Failed requests:        0
Requests per second:    0.99 [#/sec] (mean)
Time per request:       5029.434 [ms] (mean)
Time per request:       1005.887 [ms] (mean, across all concurrent requests)

先ほどとは違いリクエストは順列に1件ずつ処理されており、先に届いたリクエストが処理されるまで後のリクエストは処理されていません。同期処理を普通に書くとリクエストを同時に捌けなくなってしまう事が分かります。

※本来Playは「マルチスレッド + イベント駆動型」なので同期処理を普通に書いてもスレッド数ぶんは同時に捌けますが、今回は説明のためスレッド数を1に設定しています。

同期処理をPromiseでラップする

では同期処理をPromiseでラップしてみるとどうでしょうか?Promiseでラップされた処理は非同期に実行されるので、これで同期処理でも同時に捌けるようになるはずです。

重い同期処理をPromiseでラップしたコントローラ
public class TestController extends Controller {

    public static F.Promise<Result> blockingHeavyWithPromise() {
        final String uniqueId = UUID.randomUUID().toString();
        Logger.debug("request start : " + uniqueId);
        F.Promise<Result> resultPromise = F.Promise.promise(new F.Function0<Result>() {
            @Override
            public Result apply() throws Throwable {
                Logger.debug("promise start : " + uniqueId);
                Thread.sleep(1000);
                Logger.debug("process end : " + uniqueId);
                return ok();
            }
        });

        return resultPromise.map(new F.Function<Result, Result>() {
            @Override
            public Result apply(Result result) throws Throwable {
                Logger.debug("return result : " + uniqueId);
                return result;
            }
        });
    }
}

このコントローラに対して5箇所から同時にアクセスした場合、以下のようなログが吐かれます。

request start : 676db307-d8a9-4639-853c-e52026cca17c
request start : 28dcc477-4d96-483c-b6ed-50771b48bad6
request start : 7ff15ce5-ce17-4db7-98a9-71b9f068fb76
request start : e15ddb60-4efb-47da-b008-4bfc8f69a4bc
promise start : ae1432ba-bbe4-4f22-b724-26fd919334c9
process end : ae1432ba-bbe4-4f22-b724-26fd919334c9
promise start : 676db307-d8a9-4639-853c-e52026cca17c
process end : 676db307-d8a9-4639-853c-e52026cca17c
promise start : 28dcc477-4d96-483c-b6ed-50771b48bad6
process end : 28dcc477-4d96-483c-b6ed-50771b48bad6
promise start : 7ff15ce5-ce17-4db7-98a9-71b9f068fb76
process end : 7ff15ce5-ce17-4db7-98a9-71b9f068fb76
promise start : e15ddb60-4efb-47da-b008-4bfc8f69a4bc
process end : e15ddb60-4efb-47da-b008-4bfc8f69a4bc
return result : ae1432ba-bbe4-4f22-b724-26fd919334c9
return result : 676db307-d8a9-4639-853c-e52026cca17c
return result : 28dcc477-4d96-483c-b6ed-50771b48bad6
return result : 7ff15ce5-ce17-4db7-98a9-71b9f068fb76
return result : e15ddb60-4efb-47da-b008-4bfc8f69a4bc

また、処理時間は以下のようになります。

Concurrency Level:      5
Time taken for tests:   5.102 seconds
Complete requests:      5
Failed requests:        0
Requests per second:    0.98 [#/sec] (mean)
Time per request:       5101.675 [ms] (mean)
Time per request:       1020.335 [ms] (mean, across all concurrent requests)

リクエストの受け付け自体は同時に行えていますが、今度はPromiseの実行部分が詰まっているように見えます。処理時間はPromiseでラップする前と変わりませんし、これでは意味がありません。

Promiseでラップ=新規スレッド立ち上げではない

PlayでPromiseを作成する際には暗黙的にGlobalのExecutionContextが渡されており、Promiseの処理はそのExecutionContextによって実行されます。

詳しくは下記のサイトにまとまっていますのでそちらをご覧ください。非常に参考になります。

mashi.hatenablog.com

要するに、ただPromiseを使って同期処理をラップしただけでは非同期処理にはならないという事らしいです。よく見たらPlayの公式documentationにも似たような事が書いてありますね。

ThreadPools

このため、Future でブロッキングコードをラップするという誘惑に駆られるかもしれないことに注意してください。こうすることではノンブロッキングになりませんし、ブロッキングが他のスレッド内で起こるかもしれません。使用しているスレッドプールがブロッキングを扱うための十分なスレッドを持っていることを確かめる必要があります。

別ExecutionContextを明示してPromiseでラップする

長くなりましたが、同期処理をPromiseでラップしたい際にはメインで使っているものとは別のExecutionContextを明示して渡す、というのが正しそうです。Playでは複数のExecutionContextをapplication.confで定義できます。

Promiseに渡す用のExecutionContextを定義し、それを使ってPromiseを作成してみます。

play {

    akka {
        event-handlers = ["akka.event.slf4j.Slf4jEventHandler"]
        loglevel = WARNING

        actor {

            default-dispatcher = {
                fork-join-executor {
                    parallelism-min = 1
                    parallelism-max = 1
                }
            }
            
            promises-dispatcher = {
                fork-join-executor {
                    parallelism-min = 10
                    parallelism-max = 10
                }
            }
        }
    }
}
重い同期処理を別ExecutionContextを明示してPromiseでラップしたコントローラ
public class TestController extends Controller {

    public static F.Promise<Result> blockingHeavyWithPromise() {
        ExecutionContext executionContext = Akka.system().dispatchers().lookup("play.akka.actor.promises-dispatcher");
        final String uniqueId = UUID.randomUUID().toString();
        Logger.debug("request start : " + uniqueId);
        F.Promise<Result> resultPromise = F.Promise.promise(new F.Function0<Result>() {
            @Override
            public Result apply() throws Throwable {
                Logger.debug("promise start : " + uniqueId);
                Thread.sleep(1000);
                Logger.debug("process end : " + uniqueId);
                return ok();
            }
        },executionContext);

        return resultPromise.map(new F.Function<Result, Result>() {
            @Override
            public Result apply(Result result) throws Throwable {
                Logger.debug("return result : " + uniqueId);
                return result;
            }
        });
    }
}

このコントローラに対して5箇所から同時にアクセスした場合、以下のようなログが吐かれます。

request start : 8b458e3e-a60b-467b-ae03-868115e71942
promise start : 8b458e3e-a60b-467b-ae03-868115e71942
request start : b0d248e2-5bd4-43d4-9bb5-0e3cd575dfd6
request start : 7de18236-a6f7-44b9-b427-8e1126ace14e
promise start : b0d248e2-5bd4-43d4-9bb5-0e3cd575dfd6
request start : d2f7df3a-fddb-4aaa-af3f-3888f15c0979
promise start : 7de18236-a6f7-44b9-b427-8e1126ace14e
promise start : d2f7df3a-fddb-4aaa-af3f-3888f15c0979
request start : b448a9f2-cb15-4547-b79d-e5b2627e6a9e
promise start : b448a9f2-cb15-4547-b79d-e5b2627e6a9e
process end : b0d248e2-5bd4-43d4-9bb5-0e3cd575dfd6
process end : d2f7df3a-fddb-4aaa-af3f-3888f15c0979
process end : 8b458e3e-a60b-467b-ae03-868115e71942
process end : 7de18236-a6f7-44b9-b427-8e1126ace14e
return result : 8b458e3e-a60b-467b-ae03-868115e71942
return result : b0d248e2-5bd4-43d4-9bb5-0e3cd575dfd6
process end : b448a9f2-cb15-4547-b79d-e5b2627e6a9e
return result : d2f7df3a-fddb-4aaa-af3f-3888f15c0979
return result : b448a9f2-cb15-4547-b79d-e5b2627e6a9e
return result : 7de18236-a6f7-44b9-b427-8e1126ace14e

また、処理時間は以下のようになります。

Concurrency Level:      5
Time taken for tests:   1.083 seconds
Complete requests:      5
Failed requests:        0
Requests per second:    4.62 [#/sec] (mean)
Time per request:       1082.881 [ms] (mean)
Time per request:       216.576 [ms] (mean, across all concurrent requests)

リクエストも同時に捌けていますし、Promiseも詰まっていません。処理時間も問題ありませんし、やっと求めていた動きになりました。

結論

Playで同期処理をPromiseでラップする時は、明示的に別のExecutionContextを渡すべき

色々理解不足の点もありますので、何かおかしなところありましたら教えてください!