書籍「Javaパフォーマンス」を読んで
監訳者の@cero-tさんから頂きました。@cero-tさん、ありがとうございます。
- 作者: Scott Oaks,アクロクエストテクノロジー株式会社（監訳）,寺田佳央（監訳）,牧野聡
- 出版社/メーカー: オライリージャパン
- 発売日: 2015/04/11
- メディア: 大型本
- この商品を含むブログ (3件) を見る
しかし、実際に色々な案件の解析を繰り返すと、性能遅延の要因は多種多様です。過去に遭遇した代表的なものには、GC以外にも以下のような遅延要因があります。
- アプリケーションの不効率なロジック (ループ過多、オブジェクト生成過多)
- 過度なロック、同期漏れ/volatile漏れから無限ループ発生によるCPU消費
- ローカルJVM内でリモートEJBを呼び出すことによるシリアライズ遅延
- JDBC executeBatch()未使用でのバルク更新
- JPAのフェッチ設定誤り(N+1問題)による大量SQL発行
- 初期化コストの高いFactoryの多重初期化 (EntityManagerFactory, パーサのFactory)
本書 Javaパフォーマンス のスコープは非常に広く、上記のようなJVM 〜 Java SE API 〜 Java EEの広い範囲の性能課題について触れています。本書のような内容が日本語では今までなかったため、トラブル時にはJava SeriesのJava Performanceで苦戦しながら調べていましたが、本書も机の上に置いておこうと思います。
以下、個人的に嬉しかった部分をまとめます。
JITに関する言及が嬉しい
JITがどのようなコードをコンパイル対象としていて、どのようなタイミングでコンパイルされるのか、各種閾値やOn Stack Replacement、エスケープ分析について書籍で見かけたことがなかったため、仕組みを理解する上で役立ちました。
トラブルが起こると『どういう仕組みで問題が起こったのか』の説明が必要となるケースがよくあります。コードキャッシュの溢れが起こった場合に『そもそもJITって？』の説明を求められた場合に参考にしようと思います。
具体的なGCログが嬉しい
CMS-GCのpromotion failedやconcurrent mode failure、G1GCのto-space overflowやFullGCの発生など、何らかのチューニングを行った方が良い状況を示すGCログが具体的に示されているため、トラブル時にすぐに使える内容になっています。
PostgreSQL JDBCドライバのタイムアウト設定
OracleのJDBCドライバと同様に、PostgreSQLのJDBCドライバにも同様のタイムアウト設定が用意されています。@yamadamnさんがWebLogicServer + Oracle JDBC向けにまとめた資料Oracle JDBCドライバプロパティの活用を参考に、WildFly + PostgreSQL版のタイムアウト設定を以下にまとめます。
データベース接続時のタイムアウト
PostgreSQLのデータベース接続時のタイムアウトには2種類のパラメータがあります。いずれもデフォルトは未設定で、Javaのレイヤではタイムアウトの設定はされず、NW障害時やDBハングアップ時にはOSのTCP接続タイムアウトまで待ちます。
loginTimeout=<秒>
このタイムアウト設定はTCP接続のタイムアウトではなく、ログイン処理全体のタイムアウトを示します。PostgreSQLへのログイン処理は、大まかに4つのステップに分かれていますが、これら4ステップの完了までがタイムアウトの範囲です。
PostgreSQL JDBCのログイン処理の流れ
1. java.net.Socket.connectによるTCP接続
2. Startup messageの送信
(ユーザ名、接続先DB、クライアント側の文字エンコーディング送信など)
3. 認証要求
4. Initial Queryの実行 (SET extra_float_digits = 3 の実行)
loginTimeoutの値を超えてもログイン処理が完了しない場合、タイムアウト監視スレッドがログイン処理のスレッドに割込みを掛けて、以下のような例外が出力されます。
org.postgresql.util.PSQLException: 接続試行がタイムアウトしました。 at org.postgresql.Driver$ConnectThread.getResult(Driver.java:374) at org.postgresql.Driver.connect(Driver.java:286) at java.sql.DriverManager.getConnection(DriverManager.java:664) at java.sql.DriverManager.getConnection(DriverManager.java:208) at net.agetsuma.jdbc.Main.main(Main.java:32)
connectTimeout=<秒> (9.3-1103より有効)
2015/01/02にリリースされたVersion 9.3-1103より有効なパラメータで、loginTimeoutと異なり、TCP接続時のみに着目したタイムアウトです。
具体的には、PostgreSQLに対して接続する時に実行するjava.net.Socket.connectメソッドの引数に渡しています。
// org.postgresql.core.PGStreamのコンストラクタから抜粋 Socket socket = new Socket(); socket.connect(new InetSocketAddress(hostSpec.getHost(), hostSpec.getPort()), timeout);
loginTimeoutとconnectTimeoutのどっちを使う？
loginTimeoutはconnectTimeoutの範囲を兼ねるため、NW障害やDB過負荷を考慮したタイムアウトとしてはloginTimeoutのみで十分と思います。
ソケット読み込み時のタイムアウト
Oracleと同様に、setQueryTimeoutでは救えないSQL実行中のDBハングアップなどの障害を考慮して、ソケット読み込みタイムアウトを設定することが可能です。
socketTimeout=<秒>
このタイムアウトを超えると以下のような例外が投げられます。
org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend.
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:281)
at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:562)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:420)
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:305)
at nagetsu.jdbc.Main.main(Main.java:39)
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
...
各JDBCプロパティのWildFlyデータソース設定方法
JDBCプロパティはCLIによって設定可能です。以下の例では、データソース名PostgresDSに対してloginTimeoutを60秒、socketTimeoutを600秒に設定しています。
data-source add --name=PostgresDS --jndi-name=java:/jboss/PostgresDS --driver-name=postgresql-9.3-1103.jdbc41.jar --connection-url=jdbc:postgresql://192.168.1.1/test --max-pool-size=xx --min-pool-size=xx --initial-pool-size=xx --pool-prefill=true --check-valid-connection-sql="SELECT 1" --set-tx-query-timeout=true --user-name=postgres --password=postgres --enabled=true /subsystem=datasources/data-source=PostgresDS/connection-properties=loginTimeout:add(value=60) /subsystem=datasources/data-source=PostgresDS/connection-properties=socketTimeout:add(value=600)
CDI1.2によるbean-discovery-modeの見直し
2014年4月にCDI仕様のマイナーアップデート CDI1.1 -> CDI1.2 *1が行われ、@java.inject.Singletonが付与されたクラスはデフォルトではインジェクションできるBean対象から外れました。
後方互換性のない変更であるため、以下にまとめます。
default bean-discovery-modeの見直し
CDI1.1 (Java EE7) から導入されたbean-discovery-modeについての詳細は過去の記事にまとめていますが、簡単にいうと、以下の場合にどのクラスをインジェクション対象としてスキャンするかの仕様が見直されました。
@java.inject.Singletonがスキャン対象から除外された
冒頭に書いたとおり、@javax.inject.Singletonはデフォルトのスキャン対象から除外されたため、以下のようなコードはCDI1.2よりデプロイ時にエラーになります。
@Path("/echo") @RequestScoped public class EchoResource { @Inject EchoService service; @GET public String echo(@QueryParam("name") String name) { return service.echo(name); } } @java.inject.Singleton public class EchoService { public String echo(String name) { return "Hello " + name; } }
CDI1.2に準拠しているWildFly8.2.0で試すと、デプロイ時に以下のような例外メッセージが出力されます。@Singletonがスキャン対象から外されたため、依存性の解決例外になっています。
2015-01-11 16:12:54,944 ERROR [org.jboss.msc.service.fail] (MSC service thread 1-1) MSC000001: Failed to start service jboss.deployment.unit."CDITest.war".WeldStartService: org.j
boss.msc.service.StartException in service jboss.deployment.unit."CDITest.war".WeldStartService: Failed to start service
...
Caused by: org.jboss.weld.exceptions.DeploymentException: WELD-001408: Unsatisfied dependencies for type EchoService with qualifiers @Default
シングルトンをインジェクションしたい場合の対処
思い当たる範囲で、4つの対処があります。
対処案1. インジェクション先を@Singletonにする
インジェクション先のクラスのスコープを@Singletonにすることで、依存先のServiceクラスに『インジェクション先にスコープを合わせる』ことを示す@Dependentを付与すると、Serviceはシングルトンになります。
この案が使えるのは、インジェクション先(例ではJAX-RSエンドポイント)が状態を持たない場合のみです。以下のように、フィールドに状態を持っていた場合、@Singletonでは最初のリクエスト時にしかパラメータが設定されません。
@Path("/echo") @javax.inject.Singleton public class EchoResource { @Inject EchoService service; // ↓ 最初の1回目のリクエストしかパラメータが反映されない @QueryParam("name") String name; @GET public String echo() { return service.echo(name); } } @Dependent public class EchoService { public String echo(String name) { return "Hello " + name; } }
JAX-RSとCDIを組み合わせる場合はこの案でもなんとかなりますが、フィールドにフォーム入力値などの状態を持つ事が多いJSFと組み合わせる場合は対処案1は使えません。
追記: 書いてはみましたが、Serviceをシングルトンにしたいだけなのに、JAX-RSエンドポイントを変更するこの案はあんまりお勧めできません。
対処案2. @Stereotypeを使う
CDI1.2より@Steraotypeによって自作したアノテーションが付与されていた場合、デフォルトのスキャン対象となっているため、この仕組みを利用します。
ステレオタイプとは、スコープや@Transactionalなど、Beanの機能を示すアノテーションをまとめる仕組みです。JSF2ユーザは、一度は@Modelを使ったことがあると思いますが、@ModelのJavadocを見ると、@Stereotypeによって、@RequestScopedと@Namedを組み合わせたアノテーションであるとわかります。
@Singleton単体ではスキャン対象となりませんが、@Stereotypeが付与されたアノテーションが付与されたクラスはスキャン対象となるため、以下のように@Singletonをラップしたアノテーションを作ります。
@Singleton @Stereotype @Target(TYPE) @Retention(RUNTIME) public @interface Service { }
作成したアノテーションを@Singletonの代わりに付与します。Spring Framework風に@Serviceにしてみました。
@Service public class EchoService { public String echo(String name) { return "Hello " + name; } }
対処案1と比べて一手間掛かりますが、デメリットは特にありません。
対処案3. @ApplicationScopedを使う
リクエスト毎にインスタンス生成させない方法として、アプリケーションスコープを使う案もあります。今まではアプリケーションで共有のコンフィグ情報やキャッシュなどを持たせる印象が強いアプリケーションスコープですが、1つのインスタンスを共有する観点ではシングルトンと同じように使えます。
@ApplicationScoped public class EchoService { public String echo(String name) { return "Hello " + name; } }
対処案4. ServiceはEJBで作る
スコープに困ったら、Serviceクラスのようなトランザクション境界となるクラスはJavaEE6時代と同様にEJBで作るのもありだと思います。
@Stateless public class EchoService { public String echo(String name) { return "Hello " + name; } }
個人的には@ApplicationScopedはアプリケーション全体の状態を持たせる場合に使いたいため、案2の@Stereotypeを使う案が好きです。シンプルに使う場合は案3の@ApplicationScopedがおすすめです。
スキャン対象の拡大
@Singletonがスキャン対象から外れた修正以外として、CDI1.2では新たなスキャン対象の追加も行われています。
- @Interceptor と @Decorator
- @Stereotypeを持つアノテーションが付与されたクラス
ステレオタイプについては前述の通りです。特に@Interceptorが地味に有効で、インターセプタ実装クラスにスコープアノテーションを付ける必要がなくなりました。
@InterceptorBinding @Target({TYPE,METHOD}) @Retention(RUNTIME) public @interface Logging { } // @Dependent <<== CDI1.2からはスコープがなくてもスキャンされる @Interceptor @Logging @Priority(APPLICATION + 10) public class LoggingInterceptor { @AroundInvoke public Object log(InvocationContext ic) throws Exception { System.out.println("logging ..."); return ic.proceed(); } } @Service public class EchoService { @Logging public String echo(String name) { return "Hello " + name; } }
インターセプタのスコープは？と言われても違和感があったので、嬉しい修正です。
まとめ
- CDI1.2 マイナーバージョンアップが2014/4に行われた
- beans.xmlがない場合のスキャン対象Beanが変更
- @javax.inject.Singletonはスキャン対象から除外された
- @Interceptor/@Decorator/@Stereotypeがスキャン対象に追加された
- beans.xmlがない場合のスキャン対象Beanが変更
- この修正はJavaEE7準拠サーバにも反映されている
- GlassFish4.1、WildFly8.2.0はCDI1.2に対応済み
-XX:+DisableExplicitGCに関するJDK7とJDK8の違い
この記事は JVM Advent Calendar 2014の12/5分の記事*1です。昨日は
@jyukutyoさんのJITWatchでJITコンパイルを見よう！でした。
HotSpotには-XX:+DisableExplicitGCというオプションがありますが、この挙動がJDK8のリリースから変わっていたのでまとめます。
-XX:+DisableExplicitGC とは
System.gc()でGCリクエストされても無視するオプションです。アプリケーション中でSystem.gc()を実行されるとメジャーGCが発生します。HotSpotに任せた場合はマイナーGCで十分回収できたかもしれないので、アプリケーションでSystem.gc()を呼び出すのはあまり好ましいことではありません。
無視するといっても内部的にそんな難しいことは行われておらず、OpenJDK8のソースを見るとif文でオプションが有効だったらGCしないだけです。
jdk8u/hotspot/src/share/vm/prims/jvm.cpp
451 JVM_ENTRY_NO_ENV(void, JVM_GC(void)) 452 JVMWrapper("JVM_GC"); 453 if (!DisableExplicitGC) { 454 Universe::heap()->collect(GCCause::_java_lang_system_gc); 455 } 456 JVM_END
JDK8よりjcmd <pid> GC.runに対しても有効になる
JDK7までは -XX:+DisableExplicitGC が有効化されていても、jcmd GC.runでGCリクエストが受け付けられていたのですが、JDK8より以下のメッセージ『Explicit GC is disabled, no GC has been performed.』が返ってきてGCは動きません。
$ jcmd 18952 GC.run 18952: Explicit GC is disabled, no GC has been performed.
ソースを見ると、JDK8よりDisableExplicitGCフラグのチェックがjcmd <pid> GC.runの実装に追加されています。
jdk8u/hotspot/src/share/vm/services/diagnosticCommand.cpp
258 void SystemGCDCmd::execute(DCmdSource source, TRAPS) { 259 if (!DisableExplicitGC) { 260 Universe::heap()->collect(GCCause::_java_lang_system_gc); 261 } else { 262 output()->print_cr("Explicit GC is disabled, no GC has been performed."); 263 } 264 }
この修正による影響を受けるシステム
例えば、以下のようなシステムで影響を受けると思います。
まとめ
- JDK8より起動オプション
-XX:+DisableExplicitGC有効時にはjcmd <pid> GC.runは無視されます jcmd <pid> GC.class_histogramによってメジャーGCのリクエストをすることは可能です
*1:ええ、申し込んだのは2015/1/7ですがせっかく空いてたので
書籍「詳解Tomcat」を読んで
本書のレビューアの方から頂いたので読んでみました。以下、感想です。
- 作者: 藤野圭一
- 出版社/メーカー: オライリージャパン
- 発売日: 2014/12/26
- メディア: 大型本
- この商品を含むブログを見る
最近、Twitterのタイムラインで『はじめてのXXXや、XXX 入門じゃなくて、もっと至高のXXXとか終焉のXXXみたいな書籍が欲しい』のような意見を目にした気がしますが、本書はまさに詳解Tomcatでした。設定方法を羅列するのではなく、Tomcatはどういくアーキテクチャで成り立っていて、各機能の詳細な挙動はどのような仕様なのかがまとめられています。
1章 Tomcatとは 〜 2章 Tomcatの基本 までは、背景やインストール方法などの色々な書籍で見かける導入部分の内容です。3章 アーキテクチャからが本番です。
Tomcatアーキテクチャの文書化が嬉しい
普段Tomcatを使っている人であれば、catalina/coyoteといったキーワードはスタックトレースやログで一度は目にした方も多いと思います。本書では、Servletコンテナ実装であるCatalinaアーキテクチャ(3章)およびHTTPコネクタ実装であるCoyote(5章)の全体像が文書化されています。
server.xmlを書いていると、<Service>、<Connector>、<Engine>などのCatalinaを構成するコンポーネント名が出てきますが、お恥ずかしながら今まで私はコンフィグ例を参照しながらなんとなく設定していたので、各コンポーネントの役割が理解できていませんでした。
トラブル対応時、いざTomcatのソースを読む時にアーキテクチャを理解していることはすごく重要だと思います。自身を振り返ると『Tomcat7以前ではなぜリクエスト処理後もスレッドがプールに返らないのか？』、『maxThreadsを超えるリクエストが来た時の仕様はどうなってるの？』などの問い合わせにもっと早く対応できたなと。
Tomcat固有機能の解説が嬉しい
5章 応用機能 以降ではTomcat固有の様々な便利機能の使い方、各機能がどういう仕様なのかが詳解されています。以下のような機能の詳細な解説は他の書籍ではあまり見かけないと思います。
Apache ShiroでBCryptを使う
先日のJava EE Advant Calander 2014にApache Shiroを使ってみましたを書いたところ、Shiroのデフォルトのハッシュポリシーソルト付きSHA-256, 500000 イテレーションについて、ハッシュイテレーションのアルゴリズムをShiroのように独自実装せずに、総当たり攻撃耐性を持たせるために低速化させた既存のアルゴリズム(PBKDF2, BCrypt)もあるよ*1*2*3*4 と教えてもらったため、Shiroに組み込めないか試してみる。
ハッシュアルゴリズムをどうするか
@watarinさんのJavaでパスワードをハッシュ化するのに良い方法を調べてみたを入り口に色々と調べてみたが、以下の理由でBCrypt (Java実装はjBCrypt) を選んでみた。
- Java7で動かしたい (PBKDF2WithHMAC-SHA-256がJava8から)
- JBossEAP6.3が今のところJava8をサポートしてないため
- ここで言及されている意見
- しかし、実検証データがないのはちょっと不安
- 処理において配列アクセスの多いBCryptがGPU対策に本当によいのかは不明
- Java実装jBCryptはSpringSecurityやPicketlinkに若干の修正の上、引用されている
実装する
公式コミュニティにおいても、SHIRO-290 Create a BCrypt Hash implementationとしてBCryptサポートが要望されているが、添付されている.patch案がストレッチ強度が調整できないようになってたので、作ってみる。
BCrypt向けPasswordServiceを作る
Shiro1.2より、パスワードのハッシュ化と照合を担うPasswordServiceインタフェースが用意されているため、デフォルト実装であるDefaultPasswordServiceクラスのコードを参考にして作ってみる。
public class BCryptPasswordService implements PasswordService { public static final int DEFAULT_BCRYPT_ROUND = 10; private int logRounds; public BCryptPasswordService() { this.logRounds = DEFAULT_BCRYPT_ROUND; } public BCryptPasswordService(int logRounds) { this.logRounds = logRounds; } @Override public String encryptPassword(Object plaintextPassword) { if (plaintextPassword instanceof String) { String password = (String) plaintextPassword; return BCrypt.hashpw(password, BCrypt.gensalt(logRounds)); } throw new IllegalArgumentException( "BCryptPasswordService encryptPassword only support java.lang.String credential."); } @Override public boolean passwordsMatch(Object submittedPlaintext, String encrypted) { if (submittedPlaintext instanceof char[]) { String password = String.valueOf((char[]) submittedPlaintext); return BCrypt.checkpw(password, encrypted); } throw new IllegalArgumentException( "BCryptPasswordService passwordsMatch only support char[] credential."); } public void setLogRounds(int logRounds) { this.logRounds = logRounds; } public int getLogRounds() { return logRounds; } }
ハッシュパスワード生成コードの修正
アカウント生成時にDefaultPasswordServiceを使っている部分を今作ったBCryptPasswordServiceに置き換える。
// PasswordService ps = new DefaultPasswordService(); // ラウンド数をデフォルトから変えたい場合はコンストラクタに設定 // デフォルトは10 // PasswordService ps = new BCryptPasswordService(12); PasswordService ps = new BCryptPasswordService(); String encryptedPassword = ps.encryptPassword(form.getPassword());
コメントアウトしているように、ストレッチ強度を返る時にはコンストラクタに設定する。BCryptの特徴として、引数のラウンド数は2のXX乗のような指数で示すため、デフォルトの10を20に変更したら、計算量は2倍ではなく1024倍になるので注意。
ストレッチ強度はマシンスペックおよび許容できる遅延に応じて調整する。
shiro.iniの修正
パスワード照合時に先ほど作ったBCryptPasswordServiceが使われるように、shiro.iniのpasswordMatcherを修正する。
[main] # Default SHA-256, 500000 hash iteration, use salt #passwordService = org.apache.shiro.authc.credential.DefaultPasswordService # BCrypt PasswordService passwordService = net.agetsuma.sample.shiro.security.BCryptPasswordService passwordMatcher = org.apache.shiro.authc.credential.PasswordMatcher passwordMatcher.passwordService = $passwordService
ハッシュパスワード(例: $2a$10$e4l5...)にイテレーションのラウンド数(例では10)が組み込まれているため、shiro.iniで明示的にラウンド数を設定しなくてもパスワード照合が可能。
試しに作ってみたものの一式はGithubに置いてあります。
まとめ
*1:エフセキュアブログ : 再録：パスワードは本当にSHA-1+saltで十分だと思いますか？
*3:ユーザーのパスワードを安全に保管する方法について - 11月 - 2013 - Sophos Press Releases, Security News and Press Coverage - Sophos Press Office | Sophos News and Press Releases - ソフォス
*4:6.4. パスワードハッシュ化 — TERASOLUNA Global Framework Development Guideline 1.0.0.publicreview documentation
GlassFish4.1をなおしてみた
この記事は GlassFish Advent Calendar 2014の12/25分の記事です。昨日は
@backpaper0さんのGlassFishでセッションIDを生成してるところでした。
2013/11にGlassFishの商用サポートの終了がアナウンスされて私も不安に思っていましたが、冷静に考えるとGlassFishはそもそもオープンソース(CDDL/GPLv2)です。ソースが公開されているので、もし不具合や納得いかない動作があれば自分で修正することができます。
先日、Java EE Advant Calanderの12/17分の記事を書いていたときに既知の不具合を踏んだので試しになおしてみました。以下の修正案は、私がGlassFishのソースに適当に試行錯誤して修正したとても怪しいものなので、間違ってたらすいません。
@Transactionalの例外時に原因がセットされていない
私が踏んだ不具合はGLASSFISH-21172として既にJIRAに登録されている、Java EE7から導入された@Transactionalでトランザクション境界を設定した場合、トランザクション境界内からランタイム例外が投げられても原因がよくわからないものです。
2014/12/25現在においても、今のところ修正はされていません。
具体的には以下のようなコードを実行すると問題に当たります。
@Dependent public class OrderService { @Inject OrderRepository repository; @Transactional public Order takeOrder(Order order) { return repository.persist(order); } } @Dependent public class OrderRepository { @PersistenceContext private EntityManager em; public Order persist(Order order) { Order o = em.merge(order); throw new NullPointerException("ぬるぽ"); } }
RepositoryからNPEを投げてます。上記のコードを動かし、catchせずに無視すると、GlassFish4.1では以下のようにログ出力されます。
[2014-12-16T22:04:57.576+0900] [glassfish 4.1] [SEVERE] [] [org.glassfish.jersey.server.ServerRuntime$Responder] [tid: _ThreadID=30 _ThreadName=http-listener-1(5)] [timeMillis: 1418735097576] [levelValue
: 1000] [[
An exception has been thrown from an exception mapper class org.glassfish.jersey.gf.cdi.internal.TransactionalExceptionMapper$Proxy$_$$_WeldClientProxy.
javax.transaction.TransactionalException: Managed bean with Transactional annotation and TxType of REQUIRED encountered exception during commit javax.transaction.RollbackException: Transaction marked for
rollback.
at org.glassfish.cdi.transaction.TransactionalInterceptorRequired.transactional(TransactionalInterceptorRequired.java:105)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:483)
at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:74)
at org.jboss.weld.interceptor.chain.AbstractInterceptionChain.invokeNext(AbstractInterceptionChain.java:116)
at org.jboss.weld.interceptor.chain.AbstractInterceptionChain.invokeNextInterceptor(AbstractInterceptionChain.java:94)
at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:43)
at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:36)
at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:51)
at net.agetsuma.transactional.OrderService$Proxy$_$$_WeldSubclass.takeOrder(Unknown Source)
.. 途中省略
Caused by: javax.transaction.RollbackException: Transaction marked for rollback.
at com.sun.enterprise.transaction.JavaEETransactionImpl.commit(JavaEETransactionImpl.java:445)
at com.sun.enterprise.transaction.JavaEETransactionManagerSimplified.commit(JavaEETransactionManagerSimplified.java:854)
at com.sun.enterprise.transaction.TransactionManagerHelper.commit(TransactionManagerHelper.java:81)
at org.glassfish.cdi.transaction.TransactionalInterceptorRequired.transactional(TransactionalInterceptorRequired.java:97)
... 66 moreなんとなくロールバックしたことはわかりますが、NPEが投げられたことが原因とはわかりません。システムの保守をやっていると、『環境的な要因なのか』『入力が間違ってたのか』などの例外の原因がわからないと結構困ります。
なおしてみる
オープンソースなので、困ったらなおしてみます。バグ報告やパッチ投稿方法、ロギングの指針などコミュニティに関するルールはGlassFish Project - Community Rulesにまとまっています。
ソースのダウンロード
GlassFishのソースコードはSubversionで管理されています。とりあえずソースを確認したいだけなので、4.1タグのソースをsvn exportで持ってきます。
svn export https://svn.java.net/svn/glassfish~svn/tags/4.1
ソースコードを読む
例外のスタックトレースを改めて見ると、JTA実装であるJavaEETransactionImpl.javaの445行目において、commitを試みたが既にトランザクションがロールバック確定とマーキングされていたので、RollbackExceptionを投げたとあります。
Caused by: javax.transaction.RollbackException: Transaction marked for rollback.
at com.sun.enterprise.transaction.JavaEETransactionImpl.commit(JavaEETransactionImpl.java:445)JavaEETransactionImpl.commitメソッドを見てみます。
com.sun.enterprise.transaction.JavaEETransactionImpl.commit()メソッド (445行目付近)
439 if ( isRollbackOnly() ) { 440 // rollback nonXA resource 441 if ( nonXAResource != null ) 442 nonXAResource.getXAResource().rollback(xid); 443 444 localTxStatus = Status.STATUS_ROLLEDBACK; 445 throw new RollbackException(sm.getString("enterprise_distributedtx.mark_rollback")); 446 }
JavaEETransactionalImpl.commit()の445行目で、commit()実行時に既にjavax.transaction.Transaction.setTransactionRollback()メソッドの実行によって、ロールバックすべきとマーキングされていた場合、ロールバックの上、さらにRollbackExceptionがスローされています。
このjavax.transaction.RollbackExceptionのjavadocを見ると、RollbackExceptionには例外causeを引数に取るコンストラクタは定義されていないことに気づきます。例外スタックトレースにcauseが入ってこないのは、ここのコードが原因のようです。しかし、例外の原因を設定するコンストラクタがなければ、この部分を修正して対処することは難しいと思いました。
次に、そもそもランタイム例外であるNPEが投げられてロールバックが確定しているのに、何故コミットを実行しようとしているのかが気になりました。あえてJavaEETransactionalImpl.commit()を実行によってロールバックさせずに、最初からロールバックを実行すれば良いのではと。
そこで、コミットを呼び出しているコードを探してみます。
org.glassfish.cdi.transaction.TransactionalInterceptorRequired.transactionalメソッド
69 @AroundInvoke 70 public Object transactional(InvocationContext ctx) throws Exception { ... 途中省略 91 Object proceed = null; 92 try { 93 proceed = proceed(ctx); 94 } finally { 95 if (isTransactionStarted) 96 try { 97 getTransactionManager().commit(); 98 } catch (Exception exception) { 99 String messageString = 100 "Managed bean with Transactional annotation and TxType of REQUIRED " + 101 "encountered exception during commit " + 102 exception; 103 _logger.log(java.util.logging.Level.INFO, 104 CDI_JTA_MBREQUIREDCT, exception); 105 throw new TransactionalException(messageString, exception); 106 } 107 }
proceed(ctx)の中から例外が投げられても、問答無用でcommit()しています。
proceedメソッドの挙動が気になります。このメソッドは今確認したTransactionalInterceptorRequiredクラスの親クラスTransactionalInterceptorBaseクラスで定義されています。
org.glassfish.cdi.transaction.TransactionalInterceptorBase クラス
208 public Object proceed(InvocationContext ctx) throws Exception { ... 途中省略 224 Object object; 225 try { 226 object = ctx.proceed(); 227 } catch (RuntimeException runtimeException) { 228 Class dontRollbackOnClass = 229 getClassInArrayClosestToClassOrNull(dontRollbackOn, runtimeException.getClass()); 230 if (dontRollbackOnClass == null) { //proceed as default... 231 markRollbackIfActiveTransaction(); 232 throw runtimeException; 233 }
トランザクション境界内の処理からRuntimeExceptionが投げられた場合、@Transactional(dontRollbackOn=XXX.class)に設定されているロールバック対象外の例外でなければ、231行目でトランザクションをロールバック対象とマークし、次の行でメソッドの中で発生した例外を再スローしています。
すなわち、現在の実装は例外が発生した時点ではロールバック対象としてマーキングして、例外が再スローされていますが、すぐその後に子クラスのTransactionalInterceptorRequiredクラスでcommit()が実行されているため、既にロールバック対象としてマーキング済によるコミット時例外によって、元の例外が上書きされていることによって、例外の原因がわからない事象が発生しているようです。
TransactionalInterceptorRequiredクラスの修正アイディア
@AroundInvoke public Object transactional(InvocationContext ctx) throws Exception { ... 途中省略 Object proceed = null; try { proceed = proceed(ctx); } finally { if (isTransactionStarted) { if (ロールバックマーク済み？) { getTransactionmanager().rollback(); } else { try { getTransactionManager().commit();
上記のように、ロールバック対象としてマーキングされている場合は、コミットせずに最初からロールバックして、投げられた例外がコミット例外によって上書きされないように修正したいです。
スペック(JTA1.2)の確認
GlassFish4.1はJava EE7仕様を実装した参照実装です。コードを修正するには仕様に違反しないか注意が必要です。
今回の場合、今まではロールバック時にはRollbackExceptionが返されていましたが、修正後にはアプリから投げられたランタイム例外をそのまま投げることになります。トランザクション周りの仕様はJava Transaction API (JTA)で決まれている為、JCPのサイトから仕様のPDFを入手して読んでみます。
JTA1.2仕様をRollbackExceptionで検索しても、『ロールバック時には必ずRollbackExceptionを投げること』のような記述は見当たらないため、アプリのランタイム例外をそのまま@Transactionalを付与したメソッドの呼び出し元に返しても大丈夫そうです。
不安なのでWildFly8.2でも試してみますが、@Transactionalの中からランタイム例外を投げると、特にラップされずに返ってきます。
22:37:46,952 ERROR [io.undertow.request] (default task-2) UT005023: Exception handling request to /TransactionalTest-1.0-SNAPSHOT/rest/orders: org.jboss.resteasy.spi.UnhandledException: java.lang.NullPointerException: ぬるぽ
at org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:76) [resteasy-jaxrs-3.0.10.Final.jar:]
... 途中省略
Caused by: java.lang.NullPointerException: ぬるぽ
at net.agetsuma.transactional.OrderRepository.persist(OrderRepository.java:24) [classes:]
at net.agetsuma.transactional.OrderService.takeOrder(OrderService.java:26) [classes:]
ソースコード修正
最終的になおしてみたコードの.patchはGistにおいています。
patchコマンドで適用できます。
patch -p1 -d 4.1 < GLASSFISH-21172.patch
修正したソースコードをGlassFish本流にパッチとして盛り込みをお願いする場合は、Oracle Contributor License (OCA)へのサインとオラクル社への送付が必要です。
修正したモジュールのビルド
GlassFish全体ビルドには時間が掛かるので、修正したモジュールのみビルドします。今回の対象モジュールはweld-integrationです。
cd 4.1/appserver/web/weld-integration mvn package
GlassFish4.1はJDK7u9以上ででビルドします。JDK8でビルドすると、以下のようなメッセージが出力されて失敗します。
[WARNING] Rule 0: org.apache.maven.plugins.enforcer.RequireJavaVersion failed with message: You need JDK greater or equal than 1.7.0-09 (JDK8 not supported yet)
モジュールの差し替え
新たに生成した weld-integration.jar を、元のファイルから差し替えます。
cp target/weld-integration.jar /home/test/work/glassfish4/glassfish/modules/weld-integration.jar
統合テストの実行
GlassFishのソースにはQuicklook Testsと呼ばれる統合テストが含まれています。修正によって新たにバグを盛り込んでいないか確認したいので動かしてみます。
GlassFish Project - Community Rulesでは、maven runtestで動かせると書いてあります(mvnのこと？)。陳腐化しているようです。
試しに、普通にtestフェーズを指定して動かしてみます。テスト対象のGlassFishホームも合わせて設定してみます。
cd glassfish4/4.1/appserver/tests/quicklook
mvn -Dglassfish.home=/home/test/work/glassfish4/glassfish test
...
testng-summary:
[echo] [testng]
[echo] [testng] ===============================================
[echo] [testng] QuickLookTests
[echo] [testng] Total tests run: 120, Failures: 0, Skips: 0
[echo] [testng] ===============================================
[echo] [testng]これで良いのか自信がないですが、テストをパスしたようです。
なおした結果
ロールバックの原因となった例外がそのままスローされるので、ロールバック原因がすぐわかるようになりました。
[2014-12-23T14:35:25.032+0900] [glassfish 4.1] [WARNING] [] [javax.enterprise.web] [tid: _ThreadID=28 _ThreadName=http-listener-1(2)] [timeMillis: 1419312925032] [levelValue: 900] [[
StandardWrapperValve[org.netbeans.rest.application.config.ApplicationConfig]: Servlet.service() for servlet org.netbeans.rest.application.config.ApplicationConfig threw exception
java.lang.NullPointerException: ぬるぽ
at net.agetsuma.transactional.OrderRepository.persist(OrderRepository.java:24)
at net.agetsuma.transactional.OrderService.takeOrder(OrderService.java:26)
... 省略
