WebLogic Server 12.2.1のThreadLocal Clean Out機能を検証してみる #javaee #jpoug

本日はJava EE Advent CalendarとJPOUG Advent Calndarの12日目です。*1

WebLogic Server(以降、WLS) 12.2.1が先日10/26にリリースされました。
これは、12c Release 2(12cR2)であり、およそ3年ぶりのメジャーバージョンアップの位置付けとなっています。
目玉となる新機能としては以下があり、公式からも様々な情報が順次出てきています。

• Java EE 7 Full Support*2
• Multi Tenancy Support
• Continuous Availability

ここでは、細かいですが痒い所に手が届く新機能として、ThreadLocal Clean Outを紹介・検証してみます。

ThreadLocalとクラスローダリークのおさらい

まず、WLSに限らずJavaアプリケーションサーバ全般として、ThreadLocal利用時の注意点を一昨年のAdvent Calendarにて記事を書きました。
基本的にはThreadLocalを使った場合は、確実に破棄しないとクラスローダリークの原因になります。*3
また、記事にも少々記載していましたが、当時TomcatではThreadLocalの自動削除に対応しており、WLSでも同様の機能があるとよいなと思っていたので*4、WLS 12.2.1からの新機能として実装されたのは、そのときの意見が反映されたようにも感じ、嬉しいところです。

ThreadLocalを使ったサンプルアプリケーション

ThreadLocalはフレームワークやライブラリ内で利用されることも多いと想定され、その場合は確実に破棄したり、破棄メソッドを別途呼び出すようなガイドラインもあるでしょう。
ここではスレッドセーフでなくて、現場でトラブルが起きそうな代表格の一つ*5であるSimpleDateFormatを使った実装を考えてみます。

もちろん、JDK 8からはDate and Time APIのDateTimeFormatterが用意されており、スレッドセーフなのでこれを使うべきでしょうが、レガシーだったり安易な実装であると考えてください。

シナリオ

SimpleDateFormatを継承したクラスを利用していたが、スレッドセーフではなく、テスト時に問題が発覚した*6ために、ThreadLocalを使った実装に切り替えたというシナリオで考えてみましょう。
以下のようなサンプルとしてみました。*7

public class CustomDateFormat extends SimpleDateFormat {
    public CustomDateFormat() {
        super("yyyy-MM-dd HH:mm:ss.SSS");
    }    
}

@ApplicationScoped
@Path("now")
public class NowResource {

    private static final ThreadLocal<DateFormat> DF_LOCAL
            = ThreadLocal.withInitial(() -> new CustomDateFormat());

    @GET
    @Produces(MediaType.TEXT_PLAIN)
    public String getText() {
        DateFormat df = DF_LOCAL.get();
        
        System.out.printf("Thread: %s%n", Thread.currentThread().getName());
        System.out.printf("this identity=0x%x%n", System.identityHashCode(this));
        System.out.printf("DF_LOCAL identity=0x%x%n", System.identityHashCode(DF_LOCAL));
        System.out.printf("df identity=0x%x%n", System.identityHashCode(df));
        System.out.println();

        return df.format(new Date());
    }
}

サンプルアプリケーションの考慮点・注意点

それほど本質ではないので、飛ばしていただいて構いませんが、念のため以下について、ご留意・ご了承ください。

• package/import文は、ここでは省略しています。
• SimpleDateFormatを継承した単純なCustomDateFormatクラスをあえて作成していますが、アプリケーション内で共通化した日付書式を使いたかったシナリオとご理解ください。
  • SimpleDateFormatは、ブートストラップクラスローダにて通常はロードされるため、そのままではThreadLocalに入れてもクラスローダリークは発生しないはずです。
  • CustomDateFormatは、Javaアプリケーションサーバが実装しているWebアプリケーション用のクラスローダ(WLSではweblogic.utils.classloaders.ChangeAwareClassLoader)にてロードされるクラスとしています。
• NowResourceはJAX-RSのリソースクラスとしておき、都度インスタンス化される必要もないため、CDIの@ApplicationScopedを組み合わせています。
  • javax.ws.rs.core.Applicationを継承したクラスも必要ですが、ここでは省略しています。
  • @ApplicationScopedであるため、ThreadLocalの宣言はstaticでなくてもよいですが、スレッドに紐付けて管理されるためstaticで定義することが比較的多いかと思います。
  • JDK 8から導入されたThreadLocal.withInitialを使って微妙にラムダ式を使っていますが、それほど意味はありません。後述しますが、従来から利用していたであろうinitialValue()をオーバーライドしてもよいでしょう。
  • System.outは本番用アプリケーションでは使うべきではないですが、あくまでデバッグ目的の検証用・サンプルということでご理解ください。

実行してみる

上記のサンプルアプリケーションをWLS 12.2.1にデプロイし、実行してみましょう。
ブラウザや任意のHTTPクライアントで「http://host:port/context-root/application-path/now」にアクセスしてみてください。*8
何度か実行すると、以下のような形で標準出力に出力されました。

Thread: [ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'
this identity=0x52097801
DF_LOCAL identity=0x5bc771ce
df identity=0x2f93ea4c

Thread: [ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'
this identity=0x52097801
DF_LOCAL identity=0x5bc771ce
df identity=0x7b243b31

Thread: [ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'
this identity=0x52097801
DF_LOCAL identity=0x5bc771ce
df identity=0x7b243b31

Thread: [ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'
this identity=0x52097801
DF_LOCAL identity=0x5bc771ce
df identity=0x2f93ea4c

thisやDF_LOCALは、当たり前ですが何度実行してもオブジェクトIDに変化はありません。
dfのところに注目すると、WLSの実行スレッド(上記であればExecuteThread: '0'と'2')ごとにオブジェクトIDが異なるのが確認できます。
言い換えると同じスレッドであれば、CustomDateFormatが再利用されているのが分かります。

• ExecuteThread: '0' → 0x2f93ea4c
• ExecuteThread: '2' → 0x5bc771ce

これでめでたしめでたし！という訳には残念ながら行きません。
ThreadLocal#remove()を呼び出す箇所もないため、再デプロイすることで、基本的にクラスローダリークにつながるはずです。

EagerThreadLocalCleanupを有効にする

ようやく本題のところに入っていきましょう。ThreadLocal Clean Outのドキュメントを確認すると、KernelMBeanにeagerThreadLocalCleanup属性があり、これを有効化すれば機能しそうです。

To clean up stray ThreadLocal use by applications and third-party libraries, configure the eagerThreadLocalCleanup attribute in the KernelMBean. The eagerThreadLocalCleanup attribute specifies whether to clean up all ThreadLocal storage from self-tuning thread pools after they have finished processing each work request.

早速有効化してみたいところですが、管理コンソールにはそれらしき設定は見当たりません。こんなときはWLST(WebLogic Scripting Tool)を使うのが定石です。WLSTの使い方はここでは説明しませんので、WLS勉強会の資料「使ってみよう WLST」などを参照してください。

まず、connectコマンドで接続して、findコマンドで属性がどこに定義されているかを探してみましょう。

wls:/offline> connect('weblogic','welcome1')
ユーザーID weblogicでt3://localhost:7001に接続しています ...
ドメイン"base_domain"に属する管理サーバー"AdminServer"に。が正常に接続されました

警告: サーバーへの接続に安全でないプロトコルが使用されました。
通信セキュリティを確保するには、かわりにSSLポートまたは管理ポートを使用する必要があります。

wls:/base_domain/serverConfig/> find('threadlocal')
すべての登録済MBeanインスタンスで"threadlocal"を検索しています...
/Servers/AdminServer                           EagerThreadLocalCleanup                            false

ここではAdminServerに定義されていることが分かりますが、複数のWLSインスタンスがあれば、それぞれ設定することになります。
なお、ドキュメントではKernelMBeanにeagerThreadLocalCleanup属性があることになっていますが、個々のWLSインスタンスはServerMBeanとして参照・設定します。そして、ServerMBeanはKernelMBeanを継承していることが、MBeanリファレンスã‚„APIドキュメントからも分かります。

それではEagerThreadLocalCleanupを有効化してみましょう。設定変更後にWLSの再起動が必要となります。

wls:/base_domain/serverConfig/> edit()

wls:/base_domain/edit/> startEdit()
編集セッションを開始しています ...
編集セッションが開始されました。変更が完了したら、必ず保存してアクティブ化してください。
wls:/base_domain/edit/ !> cd('/Servers/AdminServer')
wls:/base_domain/edit/Servers/AdminServer !> cmo.setEagerThreadLocalCleanup(true)
wls:/base_domain/edit/Servers/AdminServer !> save()
すべての変更を保存しています ...
すべての変更が正常に保存されました。
wls:/base_domain/edit/Servers/AdminServer !> validate()
変更を検証しています ...
変更が正常に検証されました
wls:/base_domain/edit/Servers/AdminServer !> showChanges()

アクティブ化されていないすべての変更:

変更されたMBean: com.bea:Name=AdminServer,Type=Server
呼び出された操作: modify
変更された属性: EagerThreadLocalCleanup
属性の古い値: false
属性の新しい値: true
サーバーの再起動が必要: true

wls:/base_domain/edit/Servers/AdminServer !> activate()
すべての変更をアクティブ化しています。しばらく時間がかかる場合があります ...
アクティブ化が完了すると、この編集セッションに関連付けられた編集ロックが開放されます。

MBeanで次の静的属性が変更されたため、
serverの再起動が必要です。
変更されたMBean: com.bea:Name=AdminServer,Type=Server
変更された属性: EagerThreadLocalCleanup

アクティブ化が完了しました

再度実行してみる

WLSの再起動が完了したら、再びアプリケーションを何度か実行してみましょう。
以下のような出力が確認できます。

Thread: [ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'
this identity=0x142db2b2
DF_LOCAL identity=0x7b62b3d4
df identity=0x78301aea

Thread: [ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'
this identity=0x142db2b2
DF_LOCAL identity=0x7b62b3d4
df identity=0x25cba42c

Thread: [ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'
this identity=0x142db2b2
DF_LOCAL identity=0x7b62b3d4
df identity=0x58d69058

Thread: [ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'
this identity=0x142db2b2
DF_LOCAL identity=0x7b62b3d4
df identity=0x38578023

thisとDF_LOCALは、(こちらも当たり前ですが)先ほどと同様に何度実行してもオブジェクトIDに変化はありません。
しかし、dfは同じ実行スレッド(ここでは、"ExecuteThread: '0'")でも、毎回オブジェクトIDが異なっており、リクエストの都度オブジェクトが再作成されている、つまりThreadLocal領域が破棄されていることが窺えます。

生成・破棄の動作を確認する

先のサンプルアプリケーションのThreadLocalの宣言を一部変更し、以下のようにします。*9

    private static final ThreadLocal<DateFormat> DF_LOCAL = new ThreadLocal<DateFormat>() {
        @Override
        protected DateFormat initialValue() {
            System.out.println("Initialized!");
            return new CustomDateFormat();
        }

        @Override
        public void remove() {
            super.remove();
            System.out.println("Removed!!");
        }
    };

これでビルド・デプロイし、再度アプリケーションを何度か実行すると以下のようになりました。

Initialized!
Thread: [ACTIVE] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)'
this identity=0x4276fc09
DF_LOCAL identity=0x771e79d2
df identity=0x49683253

Initialized!
Thread: [ACTIVE] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)'
this identity=0x4276fc09
DF_LOCAL identity=0x771e79d2
df identity=0x387e8df1

Initialized!
Thread: [ACTIVE] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)'
this identity=0x4276fc09
DF_LOCAL identity=0x771e79d2
df identity=0x5c5ffe39

Initialized!
Thread: [ACTIVE] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)'
this identity=0x4276fc09
DF_LOCAL identity=0x771e79d2
df identity=0x43972404

この結果から、initialValue()はリクエストの都度呼ばれているため、再作成されていることは分かりますが、remove()による明示的な破棄が行われていません。
WLSはオープンソースではないため、どのような実装となっているか分かりませんが、EagerThreadLocalCleanup属性を有効化しても、ThreadLocal#remove()を呼びだすのではなく、別の方法を使って実行スレッドのThreadLocal領域を破棄しているようです。

remove()が呼ばれなくても、以前にThreadLocalに紐付いていたオブジェクトは参照から外れ、通常はGC対象となるため、問題になるケースは少ないでしょう。
ThreadLocalに外部リソースを管理するクラス*10が紐づくような実装をしている場合は、注意が必要かもしれません。もっとも、その場合は自動削除に頼るのではなく、アプリケーションで明示的にThreadLocal#remove()を呼ばないと、リソースが枯渇して問題になるケースが多いはずです。

考察してみる

上記までの動作から、EagerThreadLocalCleanupの設定を常に有効にしたほうがよいのでしょうか？

今回のサンプルアプリケーションの例では、DateFormatオブジェクトをキャッシュして効率的に扱うためにThreadLocalに紐付けていました。リクエストの都度、オブジェクトが再生成されてしまうのでは、ThreadLocalを利用してスレッドセーフに扱えるよう工夫した意味もなくなってしまいます。

とはいえ、インフラ観点では、再デプロイ時にクラスローダリークが発生してしまっては、長期間安定的に運用できず、再起動による運用の負荷も上がってしまうのではないか……

ご安心ください。WLS 12.2.1のThreadLocal Clean Outのドキュメントには続きがあります。

By default, the eagerThreadLocalCleanup attribute is set to false, in which the self-tuning thread pool only cleans up ThreadLocal storage when a thread returns to a standby pool and after an application is undeployed.

Setting the eagerThreadLocalCleanup attribute to true ensures that all thread pool threads have no leftover ThreadLocal values from previous requests when running work for a new request. However, overhead occurs from cleaning up ThreadLocal storage after each work request and then reestablishing ThreadLocal values for each new request. Since some applications cache objects that are expensive to create in the ThreadLocal storage, cleaning up ThreadLocal values after each request may negatively impact performance on those applications.

つまり、EagerThreadLocalCleanupがデフォルトの無効のままであっても、アンデプロイ後にはThreadLocal領域は破棄されるとのことです。
また、EagerThreadLocalCleanupを有効にしていると、リクエストの都度にThreadLocal領域が破棄されるので、アプリケーションによってはパフォーマンスに悪影響を与える可能性についても言及されています。

クラスローダリークを検証してみる

では、念のため、同じアプリケーションをWLS 12.1.3/WLS 12.2.1で何度か再デプロイ・実行して、ヒープダンプを見てみましょう。ここではVisualVMを使ってみることにします。*11

WLS 12.1.3の場合

WLSのプロセスを右クリックしてヒープダンプを取得し、[クラス]ビューから「CustomDateFormat」でフィルタしてみます。同じクラスが複数ロードされており、クラスローダリークが発生していることが窺えます。

WLS 12.2.1の場合

同じようにWLS 12.2.1で、EagerThreadLocalCleanupは無効にしたままやってみます。CustomDateFormatが一つだけになっており、クラスローダリークは発生していなさそうなのが分かりますね。

もう少し補足

TomcatのThreadLocal自動削除機能は、アンデプロイ時にスレッドプールを破棄するという、半ば力技的な実装にも見受けられます。
これと比較して、WLS 12.2.1のThreadLocal Clean Outは、この記事を書くにあたって調べてみた限りでは、コア機能である実行スレッドプールを活かしたまま、ThreadLocal領域を破棄してくれるので、かなり実運用に耐えられる感があります。

ただし、クラスローダリークはThreadLocalだけが原因ではありません。
JDK 8以降ではPermanent領域がなくなり、代わりにネイティブ領域にMetaspaceとして確保されることになりましたが、デフォルトではMetaspaceの最大サイズは、ほぼ無制限となっています。*12
ThreadLocal以外のリークも考えられますので、運用時はMetaspaceの領域を監視したり、-XX:MaxMetaspaceSizeオプションを利用して、Metaspace領域のサイズを制限したほうが、プロセスの肥大化防止につながるので安全でしょう。

まとめ

それでは、まとめです。

• WLS 12.2.1はThreadLocal Clean Out機能があり、アプリケーションでThreadLocalを破棄し忘れても、クラスローダリークが発生する可能性が低くなりました。
• この機能はほとんどの場合、有効に動作するはずですが、それに頼ることなく、ThreadLocal#remove()を明示的に呼び出した方が安全でしょう。
• ThreadLocal以外が原因で、クラスローダリークが発生する可能性はありますので、Permanent/Metaspace領域のサイズを監視・制限することも検討しましょう。

*1:どちらも被せてしまいましたがお許しください…

*2:前リリースであるWLS 12.1.3でも部分的にJava EE 7に対応していました

*3:その後に、id:n_agetsumaさんによる記事ã‚„第十回 #渋谷javaでの資料も出て、非常に分かりやすいです

*4:それはそれでid:nekopさんからツッコミが入ったりしていた

*5:スレッドセーフでなくて現場でトラブルが発生する代表格の本丸はjava.util.HashMapですかね…

*6:実際に私も同じようなことをやらかしたことがあります…

*7:無理矢理感があるので、マサカリ投げどころ満載だと思いますが…

*8:RESTful APIとしては、現在の日時が返るだけですので、特に面白いところはありません…

*9:本質に関係ないのですが、匿名内部クラスだとダイヤモンド演算子が使えないのを今更知りました…

*10:ファイルやDBコネクションなど、一般的に明示的なclose()による破棄をしないとリソースリークが発生する

*11:先に紹介したn_agetsumaさんの記事ではEclipse Memory Analyzer(MAT)を使っており、こちらのほうが詳細な分析はできると思います

*12:この辺りの詳細は、末永さんの資料や、「Java8のHotSpotVMからPermanent領域が消えた理由とその影響」の記事が参考になります