[seasar-dotnet:1502] Re: [DBFlute] InternalBeanListMetaDataResultSetHandler の dataReader.Readの部分で時間がかかる。
kubo
[E-MAIL ADDRESS DELETED]
2009年 9月 29日 (火) 20:57:57 JST
久保(jflute)です。
ありがとうございます。
なるほど、ターゲットは完全に
IDataReaderのRead()メソッドですね。
そのIDataReaderのGetType()を見て頂けます？
もし、FetchNarrowingResultSetWrapperのRead()で
どの処理が時間が掛かっているのか調べて下さい。
(って、大した処理してないんですけどね..)
あと、FetchNarrowingResultSetFactoryのCreateDataReader()
内の挙動も調べて頂ければと。
2009/9/29 西山 はじめ <[E-MAIL ADDRESS DELETED]>:
> 西山(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 mailing list
> [E-MAIL ADDRESS DELETED]
> https://ml.seasar.org/mailman/listinfo/seasar-dotnet
>
seasar-dotnet メーリングリストの案内