[seasar-dotnet:1501] Re: [DBFlute] InternalBeanListMetaDataResultSetHandler の dataReader.Readの部分で時間がかかる。

西山 はじめ [E-MAIL ADDRESS DELETED]
2009年 9月 29日 (火) 20:31:37 JST


西山(hajimeni)です。

すいません。
ログの部分ですが、コンソールに出力した為、前後がずれてしまっ 
ています。
[while:Before]:2009/09/29 20:02:56
は、SQL文表示の後、
[Loop:Start]:2009/09/29 20:03:13
の前が正しいです。




[2009/09/29 20:20] 西山 はじめ さんは書きました。:
> 西山(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
>>>
>>
>>
> 
> 


-- 
++++++++++++++++++++++++++++++++++++++++++++++++++++++++
西山 はじめ
++++++++++++++++++++++++++++++++++++++++++++++++++++++++



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