[seasar-dotnet:1504] Re: [DBFlute] InternalBeanListMetaDataResultSetHandler の dataReader.Readの部分で時間がかかる。
kubo
[E-MAIL ADDRESS DELETED]
2009年 9月 29日 (火) 22:53:37 JST
久保(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 メーリングリストの案内