CB NANASHI管理人ブログ

2ちゃんねる自転車板「パーツ・自転車用品の使用感」スレのまとめサイト管理人◆cb774U5BmQです。 http://www.cbnanashi.com/ 広告類はすべてlivedoorのものです。

2010年01月

GAE/J、起動時間(spin up時間)短縮の試行錯誤

 cbnanashi@GAE/Jに対してprecompilationを有効にした結果、アプリケーションの起動時間(spin up時間)は多少短くなりましたが、まだ不満が残ります。さらなる起動時間の短縮のため、いろいろと試行錯誤してみました。

 なお、それぞれの個別の対策の効果はしっかり分析したわけではなく、少ない実行結果からの推測ですのでご容赦ください。

対策その1・DatastoreへのアクセスをJDOからLow Level APIにする

 いままでJDOを使用していたDatastoreへのアクセスをLow Level APIに全面的に書き換えました。

 しかしながら起動時間に関しては、数回の起動を試しましたがほとんど改善されませんでした。

 Googleのドキュメントや各種ブログの情報によると、PersistenceManagerFactoryの初期化には時間が掛かるとのことでしたので、改善に期待していましたが当てが外れました。未確認ですが、precompilationをすでにtrueにしていたため効果が出なかったのかもしれません。

 ただ、Low Level APIは思ったよりも使いやすいです。JDOに比べてエンティティの状態や、プロパティのlazy loadingなどを考慮しなくてもよい分、単純です。MemcacheにもDatastoreから取得したEntityオブジェクトをそのまま格納できます。反面、DatastoreのEntityとオブジェクト属性のマッピングを自前で行う必要がありますが、面倒くささとしてはJDBCを直接使うのと大差ありません。

 ちなみに、JDOからの移行に当たってはデータの保存を忘れることがあり、そこだけ注意が必要でした(JDOは永続化済みのオブジェクトは属性を変更するだけで保存されるため)。

対策その2・Strutsの使用を中止する

 Strutsはそれほど重いフレームワークではありませんが、起動時に設定ファイルを読んで初期化を行うためそれなりに時間が掛かっていると思われます。そこでStrutsの機能のうちアプリで使っている部分だけを抽出し、Action/ActionForm/JSPにほぼ影響が出ないようにしつつ、フルスクラッチで書き直しました(ごく一部の機能だけしか使っていないので高々25クラス位です)。struts-config.xmlに設定を書くのではなく、ソースファイル内にコードとして設定を記述するようにしました。

 結果としては、やはり大きな改善はなかったようです。

 単純なServlet+JSPのアプリは起動時間が短いため、初期化処理の削減とファイル読み込みを無くすことによる効果は、かなりあるだろうと踏んでいたのですが、こちらも残念でした。

対策その3・初期化時のクラスローディングを減らす

 初期化処理を減らしても遅いため、どうもクラスローディングが遅いのではないかと当たりをつけました。

 書き直したStrutsは、初期化時にすべてのAction/ActionFormクラスをロードする(Classオブジェクトを読み込む)作りになっていました。それを、必要となった時点でロードするように書き換えました。ちなみにコードにはpathを比較するif文がずらりと並んでいます。

 この対策は有効で、ある程度の改善が図れました。

 Google App Engine for Javaで起動時間を短縮するにはクラスローディングを減らすのが有効なようです。

対策した結果

 上記3つの対策を施し、詳細は省略しますが約50回の起動で、最小3693ms、最大14303ms、平均6884msとなりました。対策前(平均8895ms)と比較すると2000ms程度の改善です。

 またcpu_msは対策前の9385cpu_msから4363cpu_msへと半減しています。

 GAEを意識しないフレームワークではアプリ起動時に初期化を行うものが多いですし、いまさらServlet+JSPだけで開発するのも難しいので、GAE/Jに特化したフレームワークを利用するのが早道ではないでしょうか。

 ただcpu_msをこれだけ減らしても起動時間の改善は限定的でしたので、spin upに時間が掛かるのは現在のGAE/Jではどうしようもないのかもしれません(「Request was aborted」のエラーも少なくなったものの依然として発生しています)。

GAE/J、SDK 1.2.8のprecompilationの効果

明けましておめでとうございます。今年もよろしくお願い致します。諸事情により久しぶりの更新となってしまいました。

昨年末にApp Engine SDKの1.2.8、1.3.0が相次いでリリースされました。これらのバージョンでのGAE/Javaの改善点に、パフォーマンス向上が挙げられています。リフレクションの速度向上やインスタンス起動時間の短縮が図られたとのことですが、後者の一つとして1.2.8から「precompilation」が導入されました。

precompilationはApp Engine Blogによると、App Engineにデプロイする前に(?)クラスローディングの一部の作業を事前に実行することで、クラスローディングの最適化を図るもののようです。現在はオプションのため、有効にするにはappengine-web.xmlに「<precompilation-enabled>true</precompilation-enabled>」と追加する必要があるとのことです。

cbnanashi@GAE/Jでも、初期化(spin up)に時間が掛かるのは問題になっています。さすがにDeadlineExceededExceptionが起きることはありませんが、10秒以上は必要なため同じインスタンスへの後続のリクエストがエラーになってしまいます。なおエラー発生時はログには次のようなメッセージが残ります。
Request was aborted after waiting too long to attempt to service your request.
多いときには一日に数十回も発生していました(ロボットにより集中的にアクセスされた場合など)。

そのため、さっそく有効にしてどの程度高速化されるか検証してみました。

なおcbnanashi@GAE/Jで利用している主なフレームワークはStruts 1.3のみで、Spring等は使っていません。またローカル開発環境ではほぼ瞬時に起動します。(また、DatastoreへのアクセスにはJDOを使っています。1/4追記)

servlet filterのinitメソッドでログを出力しているため、そのリクエストの処理時間が、インスタンスの起動時間になるはずです。ログを適用前後それぞれ50件抽出した結果は、以下の通りとなりました。

まず無効時(SDK 1.2.51.2.6)の起動時間です。
timestamppathstatusmscpu_msapi_cpu_mssize
01-02 12:02AM 18.837/parts/4003.html2001594616601546
01-01 11:54PM 14.868/Accessory.jsp2001165511860 8
01-01 11:54PM 07.565/partsType/40.html2001026212035 3
01-01 11:40PM 52.242/parts/2478.html20015077164374512
01-01 11:10PM 01.015/parts/1575.html20014342162022587
01-01 10:34PM 41.055/parts/750.html200123601690769019
01-01 09:59PM 01.448/parts/3499.html200126161575514128
01-01 09:48PM 42.188/parts/34.html2001389315426454
01-01 08:30PM 08.122/parts/1064.html20013139162821045
01-01 08:15PM 22.096/dynimg/a0004091.jpg200144201295888
01-01 07:08PM 41.415/2001218913008 3
01-01 06:58PM 46.536/2001011512172 3
01-01 06:53PM 32.011/parts/3981.html20012722160518723
01-01 06:50PM 04.721/200982611589 3
01-01 06:37PM 52.231/partsType/92.html2001185511335 2
01-01 06:04PM 54.245/parts/2910.html20015383166617525
01-01 05:58PM 14.093/parts/1701.html2001256415630753
01-01 05:53PM 55.922/rss.xml3041202814559340
01-01 05:50PM 17.991/rss.xml3041204513742340
01-01 05:31PM 47.149/Brand.jsp2001217511764 2
01-01 05:23PM 52.242/rss.xml200158011799439642
01-01 04:43PM 27.788/xxxxx/xxxxx.jsp2009714147182320
01-01 04:40PM 35.765/parts/3203.html2001348516854545
01-01 04:40PM 23.502/2001377113805 3
01-01 04:38PM 16.661/2001652112541 3
01-01 04:36PM 16.669/parts/1944.html20013633166102764
01-01 04:13PM 09.830/parts/1709.html2001234715173453
01-01 04:09PM 49.390/parts/903.html2001186215465455
01-01 04:03PM 09.137/2001059312425 3
01-01 03:59PM 06.559/rss.xml3041232014403340
01-01 03:55PM 51.673/parts/3237.html20015039165918317
01-01 03:53PM 32.136/parts/2501.html2001311015814834
01-01 03:06PM 08.891/parts/1136.html2001290215756453
01-01 02:59PM 00.317/rss.xml3041131414345340
01-01 02:53PM 20.308/rss.xml3041015513392340
01-01 01:24PM 25.844/200990712444 3
01-01 01:20PM 14.454/parts/3259.html2001038015395545
01-01 01:19PM 16.143/parts/1933.html20015905158057522
01-01 12:59PM 32.588/rss.xml3041065413665340
01-01 12:41PM 11.749/parts/2938.html2001469115562455
01-01 12:36PM 51.655/parts/426.html20014816156204512
01-01 12:15PM 12.805/200980711841 3
01-01 11:57AM 15.568/partsType/37.html2001074611064 9
01-01 11:49AM 56.402/rss.xml3041182413936340
01-01 11:44AM 42.976/parts/1920.html20014632154654512
01-01 11:26AM 42.710/parts/358.html2001200315455753
01-01 11:19AM 35.990/parts/1666.html20012958157184530
01-01 11:16AM 23.905/2001046612308 3
01-01 10:55AM 08.115/parts/201.html2001293915543453
01-01 10:49AM 52.273/rss.xml3041149013878340
平均  1260814531  

次に有効時(SDK 1.3.0)の処理時間です。
timestamppathstatusmscpu_msapi_cpu_mssize
01-02 04:54PM 15.238/rss.xml30474248492340
01-02 04:54PM 15.238/rss.xml30474248492340
01-02 03:57PM 59.156/parts/2501.html2009876115758315
01-02 03:54PM 07.624/rss.xml30479988920340
01-02 03:06PM 41.351/dynimg/a0003957.jpg2006058803886
01-02 03:06PM 31.554/parts/3583.html2009068101221085
01-02 02:49PM 55.489/rss.xml30489408998340
01-02 02:47PM 03.339/parts/1806.html200952410116833
01-02 02:37PM 11.047/parts/1264.html2001187510410453
01-02 02:29PM 36.278/parts/3357.html2001285010525835
01-02 02:26PM 34.523/parts/791.html2008519104007524
01-02 02:21PM 31.114/rss.xml30470708609340
01-02 02:16PM 39.027/partsType/28.html20063677155 4
01-02 02:03PM 45.995/parts/2.html200920997684522
01-02 01:49PM 44.252/rss.xml30474058336340
01-02 01:45PM 00.766/parts/1436.html200890210526454
01-02 01:37PM 08.859/parts/3586.html20093979737544
01-02 01:37PM 02.078/parts/3586.html200934910204544
01-02 01:33PM 15.926/partsType/72.html20048776941 3
01-02 01:33PM 08.725/partsType/72.html20062337330 3
01-02 01:29PM 09.002/parts/125.html2001375010243544
01-02 01:17PM 17.092/parts/3193.html200913299608321
01-02 01:05PM 35.745/parts/45.html2009414993111225
01-02 12:51PM 25.300/parts/3586.html20090269854544
01-02 12:38PM 48.172/parts/3635.html200100829912546
01-02 12:32PM 26.996/parts/3420.html20089889708836
01-02 12:15PM 59.170/parts/2954.html2001078410835835
01-02 12:11PM 31.676/parts/3696.html20096459737544
01-02 12:03PM 40.906/20069467583 3
01-02 11:59AM 53.877/rss.xml3041132793942350
01-02 11:53AM 42.956/parts/3310.html20073319029453
01-02 11:51AM 08.270/parts/3564.html2001181210340545
01-02 11:46AM 27.579/parts/2653.html2009794104001916
01-02 11:41AM 22.386/parts/201.html200910310429453
01-02 11:36AM 30.475/xxxxx/xxxxx.jsp304838487441500
01-02 11:26AM 46.167/partsType/91.html20057466844 2
01-02 11:14AM 50.806/rss.xml20095831087739643
01-02 11:08AM 09.891/20068867602 3
01-02 11:05AM 43.692/rss.xml304106078881340
01-02 11:01AM 18.205/rss.xml200109701054639643
01-02 10:46AM 01.560/parts/1667.html200808998264522
01-02 10:38AM 20.517/parts/749.html20011686114982208
01-02 10:08AM 13.387/parts/3223.html200951010087544
01-02 10:05AM 41.212/rss.xml30484689290340
01-02 10:03AM 23.632/parts/2931.html2001052411693455
01-02 09:58AM 29.675/rss.xml30486658628340
01-02 09:28AM 40.078/parts/3818.html20082149387544
01-02 08:57AM 42.725/20079848050 3
01-02 08:53AM 31.346/rss.xml30467508200340
01-02 08:42AM 28.266/20071667058 3
平均  88959385  

初期化が発生した処理(リクエストされたページ)の内容によって処理時間にばらつきがありますが、平均12608msから8895msと、ちょうど30%改善されていることが分かります。起動時間の短縮にはかなり有効なようです。cbnanashi@GAE/Jでは特に副作用もないようでした。

ただ、依然としてときどき10秒を超えています。App Engineのさらなる初期化時間の短縮に期待したいところです。

なお、アプリケーション側の起動時間短縮の対策としてはstruts-config.xmlから動的に設定を読み込むのではなく、静的に(ソース内部に)設定を記述するような機能を作成することを考えています。
記事検索
Recent Comments
QRコード
QRコード
  • ライブドアブログ