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

小林貴生 [E-MAIL ADDRESS DELETED]
2008年 2月 6日 (水) 10:29:58 JST 

以前もお世話になりました、小林と申します。


今回、少々困っていまして教えを請いたいと思い質問させていただきます。
多分、長文になります、すいません。


現象：
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 メーリングリストの案内