[seasar-dotnet:1507] Re: [DBFlute] InternalBeanListMetaDataResultSetHandler の dataReader.Readの部分で時間がかかる。
kubo
[E-MAIL ADDRESS DELETED]
2009年 9月 30日 (水) 23:07:04 JST
久保(jflute)です。
複雑な問題のようですね...
詳細な報告ありがとうございます。
(Javaで全く同じことしてどうなるか気になりますねぇ...)
2009/9/30 西山 はじめ <[E-MAIL ADDRESS DELETED]>:
> 西山(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 mailing list
> [E-MAIL ADDRESS DELETED]
> https://ml.seasar.org/mailman/listinfo/seasar-dotnet
>
seasar-dotnet メーリングリストの案内