特定の構成で、DBコネクションが取得できなくなる

[awaawa]

jfluteさん

awaawaです。

特定の構成で、DBコネクションが取得できなくなる事象が発生しています。

ご確認いただいてよろしいでしょうか。

【事象が発生する構成】

tomcat6

atomikos 3.8.0

seasar2

dbflute 1.0.2

tomcatのserver.xml、context.xmlにDataSource、トランザクションを定義。

jdbc.diconで、DataSource、トランザクションをjndi経由で取得。

別途jta-atomikos.diconを作成。

※jta-wls.diconの内容を修正したもの。

　jndi名を「javax.transaction.TransactionManager」→「java:comp/env/TransactionManager」に変更。

【検証前準備】

コネクションプール数を1にする。

【事象】

1リクエスト中(対象はwebアプリです。)に以下の処理が2回走った後、

SQL発行のためのコネクション取得処理でエラー(タイムアウト)になる。

※なぜか、事前に使っていたコネクションが取得できない。

　確認しているリクエストでは、RequiresNewはないので1コネクションで足りるはず。

org.seasar.dbflute.s2dao.metadata.impl.TnBeanMetaDataFactoryImpl#createBeanMetaData 75行目

この処理自体は、1度実行されるとキャッシュされるため、

1リクエスト中にアクセスするEntity(1テーブル?)の回数分リクエストをリトライすると、最終的に画面表示される。

(次の画面の表示も、Entity(1テーブル?)の回数分リクエストをリトライが必要。すでにキャッシュされているEntity分のリトライは不要。)

コネクションプール数を5などにすると、

1リクエストで複数コネクションを使用してしまいますが、正常に画面表示される。

2回目以降の同じ画面へのリクエストは1コネクションのみ使用される。(ハッシュコードで確認)

【確認内容】

事前に使っていたコネクションが取得できない根本理由がまだ分かっていないのですが、

DatabaseMetaDataの取得処理(コネクション取得も含めて)を削除すると、

エラー(タイムアウト)が出なくなりました。

ソースを見たところ、取得したDatabaseMetaDataを利用している箇所がないように見えました。

この処理を削除しても問題ないでしょうか。

【備考】

なお、以下の構成だと、事象は発生しませんでした。

tomcat6

seasar2

dbflute 1.0.2

tomcatのcontext.xmlにDataSourceのみ定義。

diconで、コネクションをjndi経由で取得。

jta.diconを利用。

すいませんが、ご確認よろしくお願いします。

[kubo]

jfluteです

awaawaさん、こんばんは

> この処理自体は、1度実行されるとキャッシュされるため、
> 1リクエスト中にアクセスするEntity(1テーブル?)の回数分リクエストをリトライすると、最終的に画面表示される。
> (次の画面の表示も、Entity(1テーブル?)の回数分リクエストをリトライが必要。すでにキャッシュされているEntity分のリトライは不要。)

ちょっとここが難しくでぱっと理解できてないのだけど...

> 事前に使っていたコネクションが取得できない根本理由がまだ分かっていないのですが、
> DatabaseMetaDataの取得処理(コネクション取得も含めて)を削除すると、
> エラー(タイムアウト)が出なくなりました。

atomikos内でDatabaseMetaDataの取得がConnectionの
ライフサイクルに影響してるんだろう、きっと。
結局、そこはDBCPの実装次第ってところなんだよね。

> ソースを見たところ、取得したDatabaseMetaDataを利用している箇所がないように見えました。
> この処理を削除しても問題ないでしょうか。

S2DaoのEntityも動かせるためのロジックが残ってるのだけど、
今のDBFluteでは一切S2DaoのEntityを動かすことはないはずなので、
その辺をしっかり整理してみようかね。
atomikosに限らず要らないDatabaseMetaDataは取らない方が無難だろうし。

とはいえ修正は大変なので、
DatabaseMetaDataをラップしたクラスを用意して、
何かしらのgetterが呼ばれたときに DatabaseMetaData を
Connectionから取得するようにしようかな...

2013/2/15 awaawa <p1us3i...@gmail.com>:

> --
> このメールは Google グループのグループ「DBFluteユーザの集い」の登録者に送られています。
> このグループから退会し、メールの受信を停止するには、dbflute+u...@googlegroups.com にメールを送信します。
> このグループに投稿するには、dbf...@googlegroups.com にメールを送信してください。
> http://groups.google.com/group/dbflute?hl=ja からこのグループにアクセスしてください。
> その他のオプションについては、https://groups.google.com/groups/opt_out にアクセスしてください。
>
>

[kubo]

jfluteです

> 1リクエスト中にアクセスするEntity(1テーブル?)の回数分リクエストをリトライすると、最終的に画面表示される。
> (次の画面の表示も、Entity(1テーブル?)の回数分リクエストをリトライが必要。すでにキャッシュされているEntity分のリトライは不要。)

わかった、キャッシュされるとgetMetaData()が呼ばれないから、
どんどんキャッシュがリクエストごとに一つずつされていけば、
すべてキャッシュが揃ったときにようやっとSQLが実行されるのね。

> Entity(1テーブル?)

その回数は、一回のリクエストでキャッシュするEntityの数次第で
変わるかな。SetupSelectしてる関連テーブルとかなら一緒に
キャッシュされるので、少し紛れがあるね。

> 事前に使っていたコネクションが取得できない根本理由がまだ分かっていないのですが、
> DatabaseMetaDataの取得処理(コネクション取得も含めて)を削除すると、
> エラー(タイムアウト)が出なくなりました。

DatabaseMetaDataの取得処理だけを削除するとどうなるかな？
getMetaData()をするとだめなのかなと。
Connectionをgetしてること自体がダメと仮定すると、
二発 select したら二発目の select も同じ現象になるだろうから。


2013/2/15 awaawa <p1us3i...@gmail.com>:

[awaawa]

jfluteさん

ご確認ありがとうございます。

> すべてキャッシュが揃ったときにようやっとSQLが実行されるのね。

そうです。わかりづらくてすいません。

> SetupSelectしてる関連テーブルとかなら一緒に

> キャッシュされるので、少し紛れがあるね。

なるほど。

> DatabaseMetaDataの取得処理だけを削除するとどうなるかな？

DatabaseMetaDataの取得処理の削除だけではダメでした。

Connectionのgetがダメみたいです。(もしかしたらclose?そんなことはないと思いますが。)

> 二発 select したら二発目の select も同じ現象になるだろうから。

論理的にはそうなるほうがスッキリしますが、そうなりませんでした。

*************************************************************************

NG

TnBeanMetaDataFactoryImpl#createBeanMetaData (テーブルA)

↓

TnAbstractBasicSqlHandler#getConnection (テーブルA)

↓

TnBeanMetaDataFactoryImpl#createBeanMetaData (テーブルB)

↓

TnAbstractBasicSqlHandler#getConnection  (テーブルB) → コネクションをとれず、タイムアウトエラー

*************************************************************************

OK

TnAbstractBasicSqlHandler#getConnection (テーブルA)

↓

TnBeanMetaDataFactoryImpl#createBeanMetaData (テーブルB)

↓

TnAbstractBasicSqlHandler#getConnection (テーブルB)

*************************************************************************

OK

TnAbstractBasicSqlHandler#getConnection (テーブルA)

↓

TnAbstractBasicSqlHandler#getConnection (テーブルB)

*************************************************************************

2013年2月15日 23:57 kubo <dbf...@gmail.com>:

[kubo]

jfluteです。

DBMSは何を使ってる？
あと、検索は selectPage() 使ってる？

可能性として、
ManualThreadDataSourceHandlerでConnectionを
一瞬keepするから、その間にメタデータ用の
getConnection()で二個目を取りにいくかも。

でも、CountLaterであれば、最初の実データ検索で、
そのkeepよりも先にメタデータ処理が走るので、
Count先のときじゃないと発生しないようにも思えるが。

いずれにせよ、ローカルではメタデータの処理で、
Connectionも取得しないようにはしてるので、
純粋にSQLのConnection取得だけになります。

2013/2/16 awaawa <p1us3i...@gmail.com>:

[awaawa]

awaawaです。

移動中のため、取り急ぎの報告で。

> DBMSは何を使ってる？

oracle11gです。

> あと、検索は selectPage() 使ってる？

使ってる箇所もありますが、事象を確認したところで使ってるかは確認しないとわからないです。

修正ありがとうございます。

ソース確認は今日夜に、動作確認は月曜日にします。

もしかしたら、

メタデータ取得の箇所をデータソースから直接取得でなく、ManualThreadDataSourceHandlerから取得に変えればいけますかね。

事象が発生しているアプリのdbflueバージョンが実際は少し古いので、パッチを当てるかバージョンを上げるか相談が必要そうなんで。

2013年2月16日土曜日 kubo dbf...@gmail.com:

[kubo]

jfluteです。

したら、ここでちょっと背景を整理させてください。

【問題のきっかけ】
実際のアプリで、
A. ConnectionPoolサイズを1にしたら発生？
B. アクセスが集中したら発生？
C. アプリ起動直後に発生？

少なくともロジックからすると C は入るのかなと。
初期化(キャッシュ)されてしまえばMetaData取得はしないから。

【DBFluteのロジック】
SQL実行とは別にEntityの初期化でgetConnection()する。
アプリ起動後の一番最初のアクセスにて、

1. メタデータのためにgetConnection()してclose()
2. SQL実行のためにgetConnection()してclose()

その後は、1は実行されない。
基本的には、一つのスレッドで同時に複数のConnectionを
取得することはない。(DBCPが正常の動作をすれば)

ただし、一パターンのみありえる。
「selectPage() and CountLaterじゃない and アプリ起動直後」
であれば、Connectionを同時に二つ取得する瞬間がありえる。
(ただ、わりと最近のバージョンではCountLaterなので、
明示的に設定をいじって無い限りまず発生しないかと)

DBFluteとしては、そのパターンが以外は、
getしてclose()しているため、
DBCP (ここでは Atomikos) が変な動きしない限りは、
Poolサイズが一つでも特に問題なし。
先ほどのパターンの場合だとPoolサイズが一つだと止まる。
Poolサイズが複数であれば、よほどの突然アクセスじゃない
限りは特に問題なし。

※Exampleで簡易な動作確認はしてみました。
(挙動はこの通りで)

【考察】
ロジック通りであれば、
DBFluteの唯一のパターンに合致している
もしくは、Atomikosが変な動きをしている。

いずれにせよ、気軽にできる回避策として、
アプリ起動時にメタデータの一括初期化をする。
http://d.hatena.ne.jp/jflute/20080307/1204898053
※自分の周りでは、結合・本番で使うようにしています
すると、初期化が起動スレッドで完結するので、
その後のアクセスではメタデータ取得は基本ないはず。

そして、1.0.3-RC1では、
そもそもメタデータの取得をしないように修正。

1. メタデータのためにgetConnection()してclose()
2. SQL実行のためにgetConnection()してclose()

の 1 は最初から実行されないようになる。

2013/2/16 awaawa <p1us3i...@gmail.com>:

[awaawa]

awaawaです。

> 【問題のきっかけ】

A+Cです。

各開発者が開発する際に、

開発マシンから共有のDBインスタンスに接続するのですが、

PROCESSESの上限値に近づいていたため、

開発マシンのプール数を見なおして、

トランザクションのネストがない接続は1にすることにしました。

その結果、アプリ起動後の数回のリクエストがエラーが発生するように。

※ただ、MetaDataが初期化(キャッシュ)されたあとのリクエストは成功する。

> 【DBFluteのロジック】

> 「selectPage()  and CountLaterじゃない and アプリ起動直後」

明示的に設定いじっていないと思いますが、月曜日に確認してみます。

> 【考察】

> いずれにせよ、気軽にできる回避策として、

> アプリ起動時にメタデータの一括初期化をする。

> そして、1.0.3-RC1では、

> そもそもメタデータの取得をしないように修正。

対応ありがとうございます。

両方とも月曜日に確認してみます。

2013年2月16日 15:37 kubo <dbf...@gmail.com>:

[awaawa]

awaawaです。

> 【DBFluteのロジック】

CountLaterになっていました。(特に設定をいじっていない。)

> アプリ起動時にメタデータの一括初期化をする。

> そして、1.0.3-RC1では、

> そもそもメタデータの取得をしないように修正。

両方とも確認して、どちらも正常に動きました。

ありがとうございました！！

時間あるときに、atomikosのソースをもう少し見てみます。

2013年2月17日 2:22 awaawa <p1us3i...@gmail.com>:

[kubo]

jfluteです

> CountLaterになっていました。(特に設定をいじっていない。)

ふむぅ、すると、Atomikosの方で、
メタデータのためのgetConnection()が走ると、
って感じだねぇ、なんだろうねぇ。

> 両方とも確認して、どちらも正常に動きました。
> ありがとうございました！！

とりあえずよかった。回避できそうですね。
initializeConditionBeanMeta()はあんまり知られてないので、
もっとプロモーションした方がいいなぁ...

2013/2/19 awaawa <p1us3i...@gmail.com>:

[awaawa]

awaawaです。

とりあえず回避できていますが、今日もう少し調べてみました。

適当なActionクラスやLogicクラスに

DataSourceをDIしてコネクション取得、クローズするだけの処理(クエリは発行しない)を入れると、

次のクエリ発行のためのコネクションの取得(TnAbstractBasicSqlHandler#getConnection)で

コネクションが取れなくなります。(プール数は1に設定。)

調査の際は、DataSourceとConnectionをラップしたクラスを用意してログ出力して確認しましたが、

取得とクローズの整合性に問題ありませんでした。

【調査してわかったこと】

1. TnAbstractBasicSqlHandler#getConnectionが1リクエスト中に複数回呼ばれても問題ない。

2. behaviorSelector.initializeConditionBeanMetaDataをServletのinitで呼んでも問題ない。

　　→1.0.2以前のTnBeanMetaDataFactoryImpl#createBeanMetaData連続複数回呼ばれても問題ない。

3. 1リクエスト中に、以下のいづれかが実行された後のTnAbstractBasicSqlHandler#getConnectionでエラーになる。

　・1.0.2以前のTnBeanMetaDataFactoryImpl#createBeanMetaData

　・適当なクラスにDataSourceをDIしてコネクション取得、クローズするだけの処理

【やってみようと思っていること】(明日時間が作れたら)

1. 1リクエスト中で、xxxBhv.warmUpCommandを連続複数回呼ぶ。(Servletのinit処理をコメントアウトして。)

2. 1リクエスト中で、適当なクラスにDataSourceをDI、コネクション取得、クローズするだけの処理を作り、

　連続複数回呼ぶ。

※1,2とも呼び出し後にクエリ発行(TnAbstractBasicSqlHandler#getConnection呼び出し)なしで。

#

# ローカル以外は、初期化時にinitializeConditionBeanMetaData()をコールしておいたほうがいいですね。

# 勉強になりました。

#

2013年2月19日 23:15 kubo <dbf...@gmail.com>:

[kubo]

jfluteです

> 2. 1リクエスト中で、適当なクラスにDataSourceをDI、コネクション取得、クローズするだけの処理を作り、
> 　連続複数回呼ぶ。

なんか、これがポイントっぽいね。
SQLを発行すればOKで、
発行しない空振りget/closeがだめみたいな。

2013/2/20 awaawa <p1us3i...@gmail.com>:

[awaawa]

awaawaです。

> SQLを発行すればOKで、
> 発行しない空振りget/closeがだめみたいな。

ビンゴです!!

コネクション取得、クローズを

コネクション取得、SQL発行(select 1 from dual)、クローズに変更したらエラーが起こらなくなりました。

元々の調査でatomikosのトランザクション制御をOFFにするとエラーにならないことは確認しているので、

atomikosのトランザクション制御を使った場合に、クエリ発行をトリガーにatomikosが何か処理しているようですね。

atomikosのソース見てみます。

2013年2月20日 11:25 kubo <dbf...@gmail.com>:

[kubo]

jfluteです

> 元々の調査でatomikosのトランザクション制御をOFFにするとエラーにならないことは確認しているので、
> atomikosのトランザクション制御を使った場合に、クエリ発行をトリガーにatomikosが何か処理しているようですね。

getConnection()しておきながらSQLを発行しないとは何事だ!?
みたいな実装になってるのかな...

※SQL発行することでclose()時に返還される仕組みになってるとか

2013/2/20 awaawa <p1us3i...@gmail.com>:

[awaawa]

awaawaです。

ソース呼んでみたら、それっぽい箇所がありました。

com.atomikos.jdbc.AtomikosConnectionProxy

private final static List ENLISTMENT_METHODS = Arrays.asList(new String[] {"createStatement", "prepareStatement", "prepareCall"});

上記の3メソッドのいづれかを読んだタイミングで、何らかの処理をしています。(statement.executeはしなくてもOK。)

内部処理をしっかり追えてませんが、

トランザクションに参加する必要があるメソッドを上記3メソッドに絞ることで

パフォーマンスを上げている感じですかね。。。うーん。

ためしに、"getMetaData"を配列に追加してみたら、

initializeConditionBeanMetaDataを明示的に呼ばなくても大丈夫でした。

そのため、ここが要因になっていることは確定で。

# ちなみにinitializeConditionBeanMetaDataの処理は、複数DBでも動くように以下にしました。

# S2Container container = SingletonS2ContainerFactory.getContainer();

# 

# BehaviorSelector[] behaviorSelectors

#  = (BehaviorSelector[]) container.findAllComponents(BehaviorSelector.class);

# for (BehaviorSelector behaviorSelector : behaviorSelectors) {

#  behaviorSelector.initializeConditionBeanMetaData();

# }

2013年2月20日 13:48 kubo <dbf...@gmail.com>:

[kubo]

jfluteです

そうですかぁ。
もちょい古いバージョンのAtomikosでは、
スレッドセーフじゃないとかあったし、
色々と意識することがありますね。

> # ちなみにinitializeConditionBeanMetaDataの処理は、複数DBでも動くように以下にしました。
おお、なるほど、それは素敵なフィードバック！
ありがとう。

2013/2/20 awaawa <p1us3i...@gmail.com>: