[seasar-dotnet:1505] Re: [DBFlute] InternalBeanListMetaDataResultSetHandler の dataReader.Readの部分で時間がかかる。
kubo
[E-MAIL ADDRESS DELETED]
2009年 9月 29日 (火) 22:55:00 JST
久保(jflute)です。
> B. OracleのAPIに依存しない形で実装(IDbCommandとか)
あと、ConnectionをQuillのDataSourceから
取得するようにしてみて下さい。
2009/9/29 kubo <[E-MAIL ADDRESS DELETED]>:
> 久保(jflute)です。
>
> ありがとうございます。
> これはもうOracle内部での話になるかもですね。
> 逆に独自実装で再現しないのが不思議なところです。
>
> 独自実装ですが、
>
> A. トランザクションを開始した状態で実行
> B. OracleのAPIに依存しない形で実装(IDbCommandとか)
> C. IDbCommandをTnBasicCommandFactory.CreateCommand()
> 経由で取得して実行
>
> をお試し下さい。
> 違いがCommandFactoryとコネクションの生成の仕方とか
> そういうのしか思いつかないですね。。。
>
> 2009/9/29 西山 はじめ <[E-MAIL ADDRESS DELETED]>:
>> 西山(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 mailing list
>> [E-MAIL ADDRESS DELETED]
>> https://ml.seasar.org/mailman/listinfo/seasar-dotnet
>>
>
seasar-dotnet メーリングリストの案内