[seasar-dotnet:1500] Re: [DBFlute] InternalBeanListMetaDataResultSetHandler の dataReader.Readの部分で時間がかかる。
西山 はじめ
[E-MAIL ADDRESS DELETED]
2009年 9月 29日 (火) 20:20:06 JST
西山(hajimeni)です。
返答ありがとうございます。
自前の実装でもバインド変数を利用しています。
DbParameterを追加しています。
============================================================
Dim conn As OracleConnection =
New OracleConnection("接続文字列")
conn.Open()
Dim sqlCommand As OracleCommand =
New OracleCommand()
sqlCommand.Connection = conn
sqlCommand.CommandText = sql
sqlCommand.Parameters.Add(New OracleParameter("?", "0"))
sqlCommand.Parameters.Add(New OracleParameter("?", "0"))
sqlCommand.Parameters.Add(New OracleParameter("?", "%あああ%"))
Dim sqlReader As OracleDataReader =
sqlCommand.ExecuteReader()
While sqlReader.Read
_logger.Debug("・・・・・・・・1行読み取り")
End While
============================================================
また、InternalBeanListMetaDataResultSetHandler の while文で
すが、dataReader.Read の行が遅いです。
A～Dまでは一瞬です。
while文を囲って計測した結果を添付します。
[while:Before]:2009/09/29 20:02:56
[Loop:Start]:2009/09/29 20:03:13
の間に、while(dataReader.Read)メソッドがあります。
今回は17秒かかっています。
ちなみに、アプリケーションを起動したまま連続して実行してもほ
ぼ同等の時間がかかります。
System.Console.WriteLine("[while:Before]:" + DateTime.Now);
while (dataReader.Read()) {
System.Console.WriteLine(" [Loop:Start]:" + DateTime.Now);
SQLや結果、クラス名は置換させてもらいました。
＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊
Dummy.DBFlute.AllCommon.S2Dao.S2DaoMetaDataExtension: DEBUG
2009-09-29 20:02:56,484 [10] ...Initializing sqlCommand for
SelectList().
Dummy.DBFlute.AllCommon.XLog: DEBUG 2009-09-29 20:02:56,484
[10]
/===========================================================================
Dummy.DBFlute.AllCommon.XLog: DEBUG 2009-09-29 20:02:56,484
[10]
RecipeBhv.SelectList()
Dummy.DBFlute.AllCommon.XLog: DEBUG 2009-09-29 20:02:56,484
[10]
=====================/
[while:Before]:2009/09/29 20:02:56
Seasar.Framework.Util.DataSourceUtil: DEBUG 2009-09-29
20:02:56,546 [10] 論理的なコネクションを取得しました
Dummy.DBFlute.AllCommon.QLog: DEBUG 2009-09-29 20:02:56,546
[10]
select dflocal.PARENT_ID as PARENT_ID, dflocal.PARENT_NO as
PARENT_NO, dflocal.PARENT_NAME as PARENT_NAME,
dflocal.MAG_ID as MAG_ID, dflocal.FENAME as FENAME,
dflocal.SUBTITLE as SUBTITLE, dflocal.SEID as SEID,
dflocal.SEVOLUME as SEVOLUME, dflocal.NO_FROM as NO_FROM,
dflocal.NO_TO as NO_TO, dflocal.SUP as SUP, dflocal.CALORIE
as CALORIE, dflocal.DUMMY_UNIT as DUMMY_UNIT,
dflocal.DUMMY_CALCULATION as DUMMY_CALCULATION,
dflocal.SALINITY as SALINITY, dflocal.SERVES as SERVES,
dflocal.SET_TYPE_NAME as SET_TYPE_NAME,
dflocal.MAIN_PARENT_ID as MAIN_PARENT_ID,
dflocal.COOKING_ADVISOR_ID as COOKING_ADVISOR_ID,
dflocal.STYLIST_ID as STYLIST_ID, dflocal.CAMERAMAN_ID as
CAMERAMAN_ID, dflocal.USABLE as USABLE,
dflocal.REPRINT_STATUS as REPRINT_STATUS, dflocal.DELETED as
DELETED, dflocal.REGISTER_USER as REGISTER_USER,
dflocal.REGISTER_PROCESS as REGISTER_PROCESS,
dflocal.REGISTER_DATETIME as REGISTER_DATETIME,
dflocal.UPDATE_USER as UPDATE_USER, dflocal.UPDATE_PROCESS
as UPDATE_PROCESS, dflocal.UPDATE_DATETIME as
UPDATE_DATETIME, dflocal.VERSION_NO as VERSION_NO
from PARENT dflocal
where dflocal.DELETED = '0'
and exists (select dfsublocal_0.PARENT_ID
from PARENT_OTHER dfsublocal_0
left outer join OTHER dfrelation_0 on
dfsublocal_0.OTHER_ID = dfrelation_0.OTHER_ID
where dfsublocal_0.PARENT_ID =
dflocal.PARENT_ID
and dfsublocal_0.DELETED = '0'
and dfrelation_0.OTHER_NAME like '%あああ
%' escape '|'
)
[Loop:Start]:2009/09/29 20:03:13
[CreateColumnNames:Before]:2009/09/29 20:03:13
[CreateColumnNames:After ]:2009/09/29 20:03:14
[CreateColumnMetaData:Before]:2009/09/29 20:03:14
[CreateColumnMetaData:After ]:2009/09/29 20:03:14
[CreateRow:Before]:2009/09/29 20:03:14
[CreateRow:After ]:2009/09/29 20:03:14
[Loop:Continue]:2009/09/29 20:03:14
[Loop:Start]:2009/09/29 20:03:14
[CreateRow:Before]:2009/09/29 20:03:14
[CreateRow:After ]:2009/09/29 20:03:14
[Loop:Continue]:2009/09/29 20:03:14
[Loop:Start]:2009/09/29 20:03:14
[CreateRow:Before]:2009/09/29 20:03:14
[CreateRow:After ]:2009/09/29 20:03:14
[Loop:Continue]:2009/09/29 20:03:14
[Loop:Start]:2009/09/29 20:03:14
[CreateRow:Before]:2009/09/29 20:03:14
[CreateRow:After ]:2009/09/29 20:03:14
[Loop:Continue]:2009/09/29 20:03:14
[Loop:Start]:2009/09/29 20:03:14
[CreateRow:Before]:2009/09/29 20:03:14
[CreateRow:After ]:2009/09/29 20:03:14
[Loop:Continue]:2009/09/29 20:03:14
[Loop:Start]:2009/09/29 20:03:14
[CreateRow:Before]:2009/09/29 20:03:14
[CreateRow:After ]:2009/09/29 20:03:14
[Loop:Continue]:2009/09/29 20:03:14
[Loop:Start]:2009/09/29 20:03:14
[CreateRow:Before]:2009/09/29 20:03:14
[CreateRow:After ]:2009/09/29 20:03:14
[Loop:Continue]:2009/09/29 20:03:14
[Loop:Start]:2009/09/29 20:03:14
[CreateRow:Before]:2009/09/29 20:03:14
[CreateRow:After ]:2009/09/29 20:03:14
[Loop:Continue]:2009/09/29 20:03:14
[Loop:Start]:2009/09/29 20:03:32
[CreateRow:Before]:2009/09/29 20:03:32
[CreateRow:After ]:2009/09/29 20:03:32
[Loop:Continue]:2009/09/29 20:03:32
[Loop:Start]:2009/09/29 20:03:32
[CreateRow:Before]:2009/09/29 20:03:32
[CreateRow:After ]:2009/09/29 20:03:32
[Loop:Continue]:2009/09/29 20:03:32
[while:After]:2009/09/29 20:03:32
Seasar.Framework.Util.ConnectionUtil: DEBUG 2009-09-29
20:03:32,797 [10] 論理的なコネクションを閉じました
Dummy.DBFlute.AllCommon.XLog: DEBUG 2009-09-29 20:03:32,797
[10] ===========/ [01m16s313ms (10) first=
{・・・・・・・・・・・・・・・・・・・・・・・・・・・}]
Dummy.DBFlute.AllCommon.XLog: DEBUG 2009-09-29 20:03:32,828
[10]
＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊＊
以上よろしくお願いいたします。
[2009/09/29 17:16] kubo さんは書きました。：
> 久保(jflute)です。
>
> 西山さん、こんにちは
>
> 20秒はちょっと異常ですね。
> 情報を整理させて下さい。
>
> まず、コストターゲットがSQL実行なのかマッピングなのか？
> っていうところですが、既に自前の実装だと遅くならない
> とのことですが、その自前の実装はバインド変数を利用して
> の実行と考えてよろしいでしょうか？
> Yesならマッピングでほぼ確定かと思いますのでOKです。
>
> そして、実際に「while (dataReader.Read()) {」のループが遅い
> とのことですが、ループ内のそれぞれの処理でどれが遅いのか
> 計って頂けますでしょうか？
> (具体的に一つ一つの処理の時間を計測願います)
>
> <A>
> columnNames = CreateColumnNames(dataReader.GetSchemaTable());
> ※最初の一回だけ実行される
>
> <B>
> columns = CreateColumnMetaData(columnNames);
> ※最初の一回だけ実行される
>
> <C>
> Object row = CreateRow(dataReader, columns);
> ※毎ループ実行される
>
> <D>
> その他リレーション周りの処理
> ※親テーブル(基点テーブル)のみの取得なので実行されないはず
> --> skipRelationLoopがtrueのはず
>
> 2009/9/29 西山 はじめ <[E-MAIL ADDRESS DELETED]>:
>> お世話になっております。
>> 西山(hajimeni)です。
>>
>> DBFluteを利用してSQLクエリーを実行した時に、なぜか時間がか
>> かってしまいます。
>> 同じクエリーを自力で構築して実行した際には、時間がかかること
>> が無く、原因追求に戸惑っています。
>>
>> デバッグで追ってみたところ、
>> InternalBeanListMetaDataResultSetHandlerクラス、
>> Handleメソッド内の
>> while (dataReader.Read()) {
>> ・・・
>> 部分で時間がかかっているようでした。
>>
>> DBFlute内で作成されたDbCommoandやDbParameter、DbConnectionと
>> 同等のものを自力で作った際には、dataReader.Reader部分でも時
>> 間がかからず処理されています。
>>
>> お手数ですが、調査方法等、何かアドバイスしていただけると幸い
>> です。
>>
>>
>> [環境]
>> DB： Oracle9.2.0.5
>> .NET： 2.0
>> 開発環境： VisualBasic 2008
>> DBFlute.NET： 0.8.9.2
>> 接続： DataDirect Connect for ADO.NET 3.2
>>
>> DBFluteでの実行時間：
>> 約20秒程度（ログから）
>> 自力でCommand、Readerを構築したときの実行時間
>> 1～2秒程度
>>
>> ///////////////
>> [親テーブル]1:n[子テーブル]n:1[別テーブル]
>>
>> [親テーブル] 7,000件
>> [子テーブル] 60,000件
>> [別テーブル] 2,000件
>>
>> というテーブルで、親テーブルを結果として取得する為に
>> 子テーブルをExistsSubQueryにし、
>> 別テーブルの検索条件で絞り込んでいます。
>> これに対して1000件絞込みまで行っています。
>>
>> Dim cb As New 親テーブルCB()
>> cb.Query().Deleted_Equal_False()
>> cb.Query().
>> Exists別テーブルList(AddressOf GetAddressOfSubQuery)
>>
>> Function GetAddressOfSubQuery() As SubQuery(Of 子テーブルCB)
>> subCB.Query().SetDeleted_Equal_False()
>> subCB.Query().Query別テーブル().
>> SetName_LikeSearch(_name,
>> New LikeSearchOption().LikeContain())
>> End Function
>>
>> [SQL]
>> ///////////////
>> SELECT
>> 親テーブル.ID
>> FROM 親テーブル
>> WHERE 親テーブル.DELETED = '0'
>> AND EXISTS (SELECT 子テーブル.ID
>> FROM 子テーブル
>> LEFT JOIN 別テーブル ON 子テーブル.ID = 別
>> テーブルID
>> WHERE 子テーブル.PARENT_ID = 親テーブル.ID
>> AND 子テーブル.DELETED = '0'
>> AND 別テーブル.NAME LIKE '%あああ%' ESCALE '|')
>> ///////////////
>> テーブル名は、置換させてもらっております。
>>
>>
>> 以上よろしくお願いいたします。
>>
>> --
>> ++++++++++++++++++++++++++++++++++++++++++++++++++++++++
>> 西山 はじめ
>> ++++++++++++++++++++++++++++++++++++++++++++++++++++++++
>>
>> _______________________________________________
>> seasar-dotnet mailing list
>> [E-MAIL ADDRESS DELETED]
>> https://ml.seasar.org/mailman/listinfo/seasar-dotnet
>>
>
>
>
--
++++++++++++++++++++++++++++++++++++++++++++++++++++++++
株式会社フジミック
システム開発センター ソフトウェア開発部
西山 創
[E-mail]：[E-MAIL ADDRESS DELETED]
〒140-0002 東京都品川区東品川3-32-42 フジテレビ別館7階
[TEL]：03-5495-1060
++++++++++++++++++++++++++++++++++++++++++++++++++++++++
seasar-dotnet メーリングリストの案内