[seasar-dotnet:764] Re: S2DAO.NET:Oracle10g への外だし SQL の実行が遅いように見える

kubo [E-MAIL ADDRESS DELETED]
2008年 2月 6日 (水) 10:46:30 JST 

久保です。

取り急ぎコメントさせていただきます。

「DBFluteは、Daoのキャッシュとかありそうなので、速そう」
ご利用のバージョンのDBFluteだとコアな部分は
S2Daoの機構そのままなのであまり変わらないはずです。

「2秒掛かっている部分がどの実行部分かどうか」
DBFluteをお使いであればDBFluteの独自のS2DaoInterceptorが
わかりやすいログを出してくれるはずです。
log4netの設定でそちら有効にしてみてください。

「時間がかかっているのは1度目のDB接続の際」
これに関して補足します。
S2Daoはアプリ起動後の最初のアクセス時にDaoの初期化をします。
そのときにメタデータを取得します。
2回目のアクセス以降はその初期化は行われません。
なので、メタデータが遅いかどうかは同じSQLを2回実行することで判明します。
1回目だけが遅ければメタデータが原因です。
2回目も変わらず遅ければメタデータはあまり関係ないことになります。

2008/2/6 小林貴生 <[E-MAIL ADDRESS DELETED]>:
> 以前もお世話になりました、小林と申します。
>
>
> 今回、少々困っていまして教えを請いたいと思い質問させていただきます。
> 多分、長文になります、すいません。
>
>
> 現象：
> Oracle10gに、.NET Framework Data Provider for Oracle を使用して
> 接続をしています。
> その中で、実にシンプルなSQLを外だしSQLを使用し発行しています。
> が、そのSQLが、２〜３秒掛かってしまいます。
>
>
> 環境：
> OS WindowsXP SP2
> JDK 5.0.12
> ANT 1.7.0
> S2Container.NET 1.2.9
> S2Dao.Net 1.0.4
> DBFlute 0.5.4
> （バージョンが古くてごめんなさい、以前質問した時と同じバージョンです。）
>
>
> 発行しているSQL：
> SELECT
>         COL_A
> >FROM
>         TABLE_A
> WHERE
>         COL_ZZ = /*pmb.ID*/10
>
>
> 対象テーブル TABLE_Aについて：
> 項目数98項目
> レコード数 数十万件
> COL_A は、プライマリキー項目です。
> また、COL_ZZ には、ユニークキーが掛かっています。
>
>
> 腑に落ちないところ（今分かっている事）：
> ・ログに出力されているSQLをCSE等で実行してみる → 0.1秒かからずに結果が返ってくる。
> ・全ての外だしSQLで遅いわけではない。1秒かからず返ってくるものもある。
> ・この外だしSQLは、コンスタントに遅い。→ コネクションプールとかでもなさそう。
> ・Oracle10gの該当テーブルについては、統計を取り直してある。→ Oracle側の問題ではなさそう。
>
>
> ログ（抜粋です。２番目のSQLが遅いです。１番目、３番目は速いです。）：
> 2008-01-28 16:01:09,437 [6] Seasar.Framework.Util.ConnectionUtil 論理的なコネクションを閉じました
> 2008-01-28 16:01:09,437 [6] Seasar.Framework.Aop.Interceptors.TraceInterceptor END Hoge.Fugo.Core.Service.Samp0010.ILogic#execute(Hoge, 080121775531, 26:12, 200802) : Hoge.Fugo.Core.Service.Samp0010.Result
> 2008-01-28 16:01:09,437 [6] Seasar.Framework.Aop.Interceptors.TraceInterceptor BEGIN Hoge.Fugo.Core.Service.Samp0010.ILogic#execute(Hoge, 080121775531, 26:12)
> 2008-01-28 16:01:09,437 [6] Seasar.Extension.ADO.Impl.BasicSelectHandler SELECT
>         COL_A
> >FROM
>         TABLE_OTHER1
> WHERE
>         COL_B = '12'
> 2008-01-28 16:01:09,437 [6] Seasar.Framework.Util.DataSourceUtil 論理的なコネクションを取得しました
> 2008-01-28 16:01:09,437 [6] Seasar.Framework.Util.ConnectionUtil 論理的なコネクションを閉じました
> 2008-01-28 16:01:09,437 [6] Seasar.Framework.Aop.Interceptors.TraceInterceptor END Hoge.Fugo.Core.Service.Samp0010.ILogic#execute(Hoge, 080121775531, 26:12) : Hoge.Fugo.Core.Service.Samp0010.Result
> 2008-01-28 16:01:09,453 [6] Seasar.Framework.Aop.Interceptors.TraceInterceptor BEGIN Hoge.Fugo.Core.Service.Samp0010.ILogic#execute(Hoge, 080121775531, 26:12, 200802, 1600, 3, 20080206, 0)
> 2008-01-28 16:01:09,453 [6] Seasar.Extension.ADO.Impl.BasicSelectHandler SELECT
>         COL_A
> >FROM
>         TABLE_A
> WHERE
>         COL_ZZ = '10'
> 2008-01-28 16:01:09,453 [6] Seasar.Framework.Util.DataSourceUtil 論理的なコネクションを取得しました
> 2008-01-28 16:01:11,515 [6] Seasar.Framework.Util.ConnectionUtil 論理的なコネクションを閉じました
> 2008-01-28 16:01:11,515 [6] Seasar.Extension.ADO.Impl.BasicSelectHandler SELECT
>         COL_A
> >FROM
>         TABLE_OTHER2
> WHERE
>         COL_B = '12'
> 2008-01-28 16:01:11,515 [6] Seasar.Framework.Util.DataSourceUtil 論理的なコネクションを取得しました
> 2008-01-28 16:01:11,515 [6] Seasar.Framework.Util.ConnectionUtil 論理的なコネクションを閉じました
>
>
> 対応した事、しようと考えている事：
>
> 外だしSQL自体が遅いと思い、
>
> １．外だしSQLにヒント文 を書き対応してみた
>
> のですが、出力されるログには、ヒント文は無くなっています。（裏では発行されているかも知れませんが。）
> そして相変わらず速くはなりませんでした。
>
> 以前の 2006/2/13 にこのメーリングリストにて
>
> > [Seasar-s2dotnet 122] Re: S2DAO.NET の実行時間
> > 杉本です。
> >
> > 時間がかかっているのは1度目のDB接続の際ですね。
> >
> > S2Dao.NETは、1度目のDB接続の際に、接続するデータベースの
> > メタデータ（テーブルやカラム、プライマリキー）を取得し
> > キャッシュを行います。
> >
> > その為、テーブル数が多い場合などは時間がかかるかもしれません。
> >
> > ただし、これは１度目のDB接続の時だけなので、10秒程度なら多くの
> > 場合、問題にならないのではないかと思います。
>
> と言う記述がありました。
>
> ですので、SQL自体は速いのだが、カラム数の多いテーブルのメタデータを取るので遅くなっているのだ。と仮定し
>
> ２．DBFlute で生成したBehavior を使用してデータを取得する。
>         DBFluteは、Daoのキャッシュとかありそうなので、速そう。
>         （すいません、そんなに丹念にソース見てないので、推測ですが。）
>
> をやってみようかと思います。速くなれば、また自己レスとして上げさせていただきます。
> （速くなると良いのですが．．．。）
>
>
> ．．．ここまで書いて思ったのですが、そもそもログの見方が違うのかも知れません。
>
> 外だしSQL1
> 2008-01-28 16:01:09,453 [6] Seasar.Framework.Util.DataSourceUtil 論理的なコネクションを取得しました
> 2008-01-28 16:01:11,515 [6] Seasar.Framework.Util.ConnectionUtil 論理的なコネクションを閉じました
> 外だしSQL2
>
> とある場合、2秒掛かっているのは、外だしSQL1 と思っていましたが、それが間違いでしょうか。
> （実は外だしSQL2？）
> で、あればご報告させていた原因から見直さないといけないかも知れないですね。
>
>
> 以上、長文、乱文にてご回答しづらいかも知れませんが、
> 皆様のご援助を賜りたいと存じます。
>
>
> よろしくお願いいたします。
>
> 小林
>
> _______________________________________________
> seasar-dotnet mailing list
> [E-MAIL ADDRESS DELETED]
> https://ml.seasar.org/mailman/listinfo/seasar-dotnet
>

seasar-dotnet メーリングリストの案内