[seasar-dotnet:1506] Re: [DBFlute] InternalBeanListMetaDataResultSetHandler の dataReader.Readの部分で時間がかかる。
西山 はじめ
[E-MAIL ADDRESS DELETED]
2009年 9月 30日 (水) 13:21:00 JST
西山(hajimeni)です。
DBFlute.NET（S2Dao.NET含む）と自前での実装の違いを詳細に調べ
た結果、原因がわかりましたので報告いたします。
詳細な条件はまだ、不明です。ただし、調査している限りの情報では、
============================================================
・EXISTS句を使用している。
・EXISTS句の中でJOINを行っている。
・JOINしたテーブルのカラムに対してバインド変数を使用して、中
間一致条件を設定している。（LIKE '%あああ%'）
・上記のバインド変数は3つ目以降である（これは違うかもしれま
せん）
・上記のバインド変数に対応した、IDbDataParameterのDBTypeに、
DbType.String が設定されている。
============================================================
以上の条件を全て満たした場合のみ、dataReader.Readが遅くなる
という現象でした。
単純な回避手段は、DbType に DbType.AnsiString を指定すること
でした。
独自実装で再現しなかった理由は、DbType の設定を何も行ってい
なかったからでした。
これ以上は、DataDirect ADO for .NET の問題であると思われます
ので、開発元のサポートに問い合わせたいと思います。
お手数をお掛けいたしました。ありがとうございます。
以上よろしくお願いいたします。
[2009/09/29 22:55] kubo さんは書きました。：
> 久保(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 メーリングリストの案内