Ext.DirectでのRPCのコンバインについて

Ext.Direct では、短時間での複数のRemote Procedure Call をまとめて処理する機能が組み込まれています。 デフォルトでは300ミリ秒以内に発生したリクエストは、まとめられてサーバーに送信されます。

この動作について検証をしてみました。Ext JS のバージョンは 4.0.7 です。 サーバーサイドは例によってxFrameworkPXを使用します。

Ext.Directコントローラー(.extdirect.php)

[php] class extdirect extends xFrameworkPX_Controller_ExtDirect { public $modules = array( ‘directm’ => array() ); public $direct = array( ‘namespace’ => ‘MyApp’, ‘descriptor’ => ‘Ext.REMOTING_API’ ); public function execute() { $this->log->trace(‘Direct Called.’); parent::execute(); } } [/php]

Module (directm.php)

[php] class directm extends xFrameworkPX_Model { public $usetable = false; public function test($param, $wait) { $log = xFrameworkPX_Log::getInstance(); $log->trace(‘Function Called. param = ‘ . $param); sleep($wait); return ‘param is ‘ . $param . ‘ — Server Time:’ . date(‘H:i:s’); } } [/php]

このような感じで、サーバーへのリクエストがあった場合に、ExtDirectコントローラーとModuleのそれぞれでログを取るようにしています。 Module のtest関数は、指定した秒数だけwaitして返ってくるというものです。

コンバインされるかどうか試す

クライアント側のJSコードです。単純にRPCを10かい繰り返します。

[js] Ext.ns(‘MyApp’); Ext.onReady(function () { var i; Ext.direct.Manager.addProvider(Ext.REMOTING_API); for(i=0; i<10; i++) { MyApp.directm.test(i, 0, function (ret) { var now = new Date(); console.log(ret + ‘ client time:’ + Ext.Date.format(now, ‘H:i:s’)); }); } }); [/js]

コンソールには次のように表示されます。待ち時間を0にしていますので一瞬で処理は終わっています。

[text] rpc.js:13param is 1 — Server Time:14:04:19 client time:14:04:19 rpc.js:13param is 2 — Server Time:14:04:19 client time:14:04:19 rpc.js:13param is 3 — Server Time:14:04:19 client time:14:04:19 rpc.js:13param is 4 — Server Time:14:04:19 client time:14:04:19 rpc.js:13param is 5 — Server Time:14:04:19 client time:14:04:19 rpc.js:13param is 6 — Server Time:14:04:19 client time:14:04:19 rpc.js:13param is 7 — Server Time:14:04:19 client time:14:04:19 rpc.js:13param is 8 — Server Time:14:04:19 client time:14:04:19 rpc.js:13param is 9 — Server Time:14:04:19 client time:14:04:19 [/text]

サーバーのログは次のようになっています。

[text] 2011-12-27 14:16:56,23 [00684] TRACE webapp/.extdirect.php – Direct Called. 2011-12-27 14:16:56,16 [00684] TRACE modules/directm.php – Function Called. param = 0 2011-12-27 14:16:56,16 [00684] TRACE modules/directm.php – Function Called. param = 1 2011-12-27 14:16:56,16 [00684] TRACE modules/directm.php – Function Called. param = 2 2011-12-27 14:16:56,16 [00684] TRACE modules/directm.php – Function Called. param = 3 2011-12-27 14:16:56,16 [00684] TRACE modules/directm.php – Function Called. param = 4 2011-12-27 14:16:56,16 [00684] TRACE modules/directm.php – Function Called. param = 5 2011-12-27 14:16:56,16 [00684] TRACE modules/directm.php – Function Called. param = 6 2011-12-27 14:16:56,16 [00684] TRACE modules/directm.php – Function Called. param = 7 2011-12-27 14:16:56,16 [00684] TRACE modules/directm.php – Function Called. param = 8 2011-12-27 14:16:56,16 [00684] TRACE modules/directm.php – Function Called. param = 9 [/text]

コントローラーは1度だけ呼び出されていて、Moduleの関数は10回呼び出されています。 リクエストがまとめられていることがわかります。 では、メソッドに遅延を入れた場合はどうなるのでしょうか。

rpc.js の10行目でのRPC呼び出しで第2引数に1を渡してみます。

[text] rpc.js:13param is 1 — Server Time:14:21:13 client time:14:21:21 rpc.js:13param is 2 — Server Time:14:21:14 client time:14:21:21 rpc.js:13param is 3 — Server Time:14:21:15 client time:14:21:21 rpc.js:13param is 4 — Server Time:14:21:16 client time:14:21:21 rpc.js:13param is 5 — Server Time:14:21:17 client time:14:21:21 rpc.js:13param is 6 — Server Time:14:21:18 client time:14:21:21 rpc.js:13param is 7 — Server Time:14:21:19 client time:14:21:21 rpc.js:13param is 8 — Server Time:14:21:20 client time:14:21:21 rpc.js:13param is 9 — Server Time:14:21:21 client time:14:21:21 [/text]

Server Time と client time を比べてみてください。10個のリクエストはサーバー上では1秒ごとに処理され、 それらがまとめてクライアントに返ってきているのがわかります。 リクエストのレスポンスは1秒ごとに返ってくるのではなく、10病後に全部のレスポンスが返ります。 ここでは10秒ですが、このリクエストが30とかまとまると確実にタイムアウトを引き起こします。 一つひとつのリクエストは1秒で返ってくるはずですが、まとめられたため30秒(デフォルトのタイムアウト)を越えてタイムアウトになる訳です。 やはり「重い処理はまとめない方がいい」ですね。

リクエストの分割

enableBufferコンフィグをfalseにすると、このリクエストのコンバインは行われなくなります。 そうすれば、一つひとつの処理を分割してリクエストすることが出来ます。 ただ、リクエストの数が多い場合は、サーバー側に負担を掛けることにもなります。 2番目の例をebanleBufferコンフィグをfalseにして実行してみます。

[text] rpc2.js:14param is 4 — Server Time:14:33:40 client time:14:33:40 rpc2.js:14param is 3 — Server Time:14:33:40 client time:14:33:40 rpc2.js:14param is 2 — Server Time:14:33:40 client time:14:33:40 rpc2.js:14param is 0 — Server Time:14:33:40 client time:14:33:40 rpc2.js:14param is 5 — Server Time:14:33:40 client time:14:33:40 rpc2.js:14param is 1 — Server Time:14:33:40 client time:14:33:40 rpc2.js:14param is 7 — Server Time:14:33:41 client time:14:33:41 rpc2.js:14param is 6 — Server Time:14:33:41 client time:14:33:41 rpc2.js:14param is 8 — Server Time:14:33:41 client time:14:33:41 rpc2.js:14param is 9 — Server Time:14:33:41 client time:14:33:41 [/text]

もどってくる順番が面白いことになっています。 サーバー側では6つのリクエストが一度に処理をされているような感じに見えます。 これはapacheの設定で変わるのだろうとおもいます。 それにしてももどってくる順番がでたらめですね。

[text] 2011-12-26 16:19:23,22 [32174] TRACE webapp/.extdirect.php – Direct Called. 2011-12-26 16:19:23,16 [32174] TRACE modules/directm.php – Function Called. param = 0 2011-12-26 16:19:24,22 [32174] TRACE webapp/.extdirect.php – Direct Called. 2011-12-26 16:19:24,16 [32174] TRACE modules/directm.php – Function Called. param = 1 2011-12-26 16:19:25,22 [32174] TRACE webapp/.extdirect.php – Direct Called. 2011-12-26 16:19:25,16 [32174] TRACE modules/directm.php – Function Called. param = 2 2011-12-26 16:19:27,22 [32174] TRACE webapp/.extdirect.php – Direct Called. 2011-12-26 16:19:27,16 [32174] TRACE modules/directm.php – Function Called. param = 3 2011-12-26 16:19:28,22 [32174] TRACE webapp/.extdirect.php – Direct Called. 2011-12-26 16:19:28,16 [32174] TRACE modules/directm.php – Function Called. param = 4 2011-12-26 16:19:29,22 [32174] TRACE webapp/.extdirect.php – Direct Called. 2011-12-26 16:19:29,16 [32174] TRACE modules/directm.php – Function Called. param = 5 2011-12-26 16:19:30,22 [32174] TRACE webapp/.extdirect.php – Direct Called. 2011-12-26 16:19:30,16 [32174] TRACE modules/directm.php – Function Called. param = 6 2011-12-26 16:19:31,22 [32174] TRACE webapp/.extdirect.php – Direct Called. 2011-12-26 16:19:31,16 [32174] TRACE modules/directm.php – Function Called. param = 7 2011-12-26 16:19:32,22 [32174] TRACE webapp/.extdirect.php – Direct Called. 2011-12-26 16:19:32,16 [32174] TRACE modules/directm.php – Function Called. param = 8 2011-12-26 16:19:33,22 [32174] TRACE webapp/.extdirect.php – Direct Called. 2011-12-26 16:19:33,16 [32174] TRACE modules/directm.php – Function Called. param = 9 [/text]

サーバーのログを見ると、一つひとつが別のリクエストして送られてきていることがわかります。

enableBufferコンフィグをfalseにせずにリクエストを分割する方法としては、 リクエストを送り、そのレスポンスでのコールバックで次のリクエストを送るという方法があります。

[js] Ext.onReady(function () { var i; Ext.direct.Manager.addProvider(Ext.REMOTING_API); i = 0; MyApp.f = function() { MyApp.directm.test(i, 1, function (ret) { var now = new Date(); console.log(ret + ‘ client time:’ + Ext.Date.format(now, ‘H:i:s’)); i++; if( i < 10 ){ MyApp.f(); } }); }; MyApp.f(); }); [/js]

こんな感じです。この方法では最初のレスポンスが返ってきてから次のレスポンスを送るので、 同期的に処理をする必要があるときには便利です。

[text] rpc3.js:14param is 0 — Server Time:14:41:48 client time:14:41:48 rpc3.js:14param is 1 — Server Time:14:41:50 client time:14:41:50 rpc3.js:14param is 2 — Server Time:14:41:51 client time:14:41:51 rpc3.js:14param is 3 — Server Time:14:41:52 client time:14:41:52 rpc3.js:14param is 4 — Server Time:14:41:53 client time:14:41:53 rpc3.js:14param is 5 — Server Time:14:41:54 client time:14:41:54 rpc3.js:14param is 6 — Server Time:14:41:55 client time:14:41:55 rpc3.js:14param is 7 — Server Time:14:41:56 client time:14:41:56 rpc3.js:14param is 8 — Server Time:14:41:57 client time:14:41:57 rpc3.js:14param is 9 — Server Time:14:41:58 client time:14:41:58 [/text]

コンソールへの表示も、1秒ごとに更新され、順番に着実に処理されてゆく様子が見て取れます。

一つひとつのリクエストを分割するのではなく、いくつかの塊でリクエストを分割して送信したい場合は、 Ext.TaskManager の力を借りるなどして、リクエストとリクエストの間に300ミリ秒以上の間隔を開けてやるという方法が使えます。