[seasar-dotnet:1503] Re: [DBFlute] InternalBeanListMetaDataResultSetHandler の dataReader.Readの部分で時間がかかる。
西山 はじめ
[E-MAIL ADDRESS DELETED]
2009年 9月 29日 (火) 21:20:35 JST
西山(hajimeni)です。
IDataReaderは、
DataDirect Connect for ADO.NET 3.2 で提供されている。
DDTek.Oracle.OracleDataReader
となります。
QuillのDataProviderでは提供されていなかった為、
DataProviderを継承したクラスを作成しています。
Public Class DDTekOracle
Inherits DataProvider
Public Sub New()
ConnectionType = "DDTek.Oracle.OracleConnection"
CommandType = "DDTek.Oracle.OracleCommand"
ParameterType = "DDTek.Oracle.OracleParameter"
DataAdapterType = "DDTek.Oracle.OracleDataAdapter"
End Sub
End Class
CreateDataReaderの挙動ですが、
1.ExecuteReader で OracleDataReader が生成される。
2.if
(!FetchNarrowingBeanContext.IsExistFetchNarrowingBeanOnThread())
{
が false となり次の処理へ。
2.if (!IsUseFetchNarrowingResultSetWrapper(cb)) {
が true となり 1 で生成した OracleDataReader を return
となっています。
[2009/09/29 20:57] kubo さんは書きました。：
> 久保(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 メーリングリストの案内