メモリ使用量の増大(解決済み)

メモリ1GBのThinkPad T42にEclipse, MySQL 5.0, JBoss4.0.2 x2つ起動してEclipse上からマルチスレッドで複数のEJBに負荷をかけて遊んでいたところ,どうもJBossのメモリ使用量の増加が目に付く.

Windowsには仮想メモリ+512MBしか与えていないので,合計で1.5GBなわけだけど,JBoss x2の起動前のメモリ使用量が合計で約500MB,双方のJBossには"-Xms128m -Xmx128"しかつけていないけど起動直後が合計で800MBくらい.

やっぱサンプルアプリの実装が悪いのかなぁ.いろんなリソースを使い終わったらすぐcloseしてるはずですが.実験を行うたびにタスクマネージャで見るとメモリ合計使用量があがっている.でもプロセスごとの使用量ではなぜかJBossはそれぞれ250MBくらいまで.計算が合わない.

JBossあげっぱなしで複数回実験を繰り返しているとしまいには,こんなエラーまでみることができました.JBossの起動時のJAVA_OPTSに"-verbose:gc"つけているのでヒープ領域の様子とかも見れてます.ヒープは関係ないように見える.Windows仮想メモリも使い果たすとWindowsが「仮想メモリそろそろなくなります」とエラーダイアログを上げてきて,これ.

[GC 59237K->51895K(130112K), 0.0549640 secs]
[GC 60023K->52025K(130112K), 0.0534009 secs]
[GC 60153K->53079K(130112K), 0.0437352 secs]
[Full GC 54619K->53258K(130112K), 0.6128452 secs]
#
# HotSpot Virtual Machine Error, Internal Error
# Please report this error at
# http://java.sun.com/cgi-bin/bugreport.cgi
#
Java HotSpot(TM) Client VM warning: Attempt to allocate stack guard pages failed.
Java HotSpot(TM) Client VM warning: Java HotSpot(TM) Client VM warning: Java HotSpot(TM) Client VM warning: Ja
va HotSpot(TM) Client VM warning: Java HotSpot(TM) Client VM warning: Java HotSpot(TM) Client VM warning: Java
 HotSpot(TM) Client VM warning: Java HotSpot(TM) Client VM warning: Java HotSpot(TM) Client VM warning: Java H
otSpot(TM) Client VM warning: Java HotSpot(TM) Client VM warning: # Java VM: Java HotSpot(TM) Client VM (1.4.2
_08-b03 mixed mode)
Attempt to allocate stack guard pages failed.
Attempt to allocate stack guard pages failed.
Attempt to allocate stack guard pages failed.
Attempt to allocate stack guard pages failed.
Attempt to allocate stack guard pages failed.
Attempt to allocate stack guard pages failed.
Attempt to allocate stack guard pages failed.
Attempt to allocate stack guard pages failed.
Attempt to allocate stack guard pages failed.
Attempt to allocate stack guard pages failed.
#
Attempt to allocate stack guard pages failed.
# Error ID: 4D555445583F57494E13120E4350500079
#
# Problematic Thread: prio=5 tid=0x4d2415f0 nid=0xba20 runnable
#

Heap at VM Abort:
Heap
 def new generation   total 9088K, used 3471K [0x10010000, 0x109e0000, 0x109e0000)
  eden space 8128K,  42% used [0x10010000, 0x10373ed0, 0x10800000)
  from space 960K,   0% used [0x108f0000, 0x108f0000, 0x109e0000)
  to   space 960K,   0% used [0x10800000, 0x10800000, 0x108f0000)
 tenured generation   total 121024K, used 53258K [0x109e0000, 0x18010000, 0x18010000)
   the space 121024K,  44% used [0x109e0000, 0x13de2a80, 0x13de2c00, 0x18010000)
 compacting perm gen  total 18944K, used 18933K [0x18010000, 0x19290000, 0x1c010000)
   the space 18944K,  99% used [0x18010000, 0x1928d450, 0x1928d600, 0x19290000)

どうにかしないと次の実験にいけん・・・.



追記メモ
Windowsタスクマネージャ JBoss起動前

ハンドル 11276
スレッド 336
プロセス 49
コミットチャージ合計 369428

JBoss2つ起動後(Xms128m Xmx128m Xss32k)

ハンドル 13253
スレッド 434
プロセス 53
コミットチャージ合計 724700

1000トランザクションくらい処理した直後(1トランザクションにつきJMS送信受信それぞれ1回ずつあり)

ハンドル 84983
スレッド 9828
プロセス 54
コミットチャージ合計 1377828

スレッドが異様に増えている.1スレッドごとに32kのJavaスタックを使うとして,増えた9400個分と仮定して掛け算すると,Javaスタックで300MB.100トランザクション限定で見てみると「スレッド数→1266まで増加」となっているので,1トランザクションごとに8くらいのスレッドが生成されていることに.しかも再利用されず,回収もされず・・・.どこをどう間違えているのやら.



追記メモ2
こんなコードで実験してみると

public class ThreadGenerator {
    private static int count = 0;
    
    public static void main(String[] args) throws Exception {
        int threadNumber = 3000;
        
        for (int i = 0; i < threadNumber; i++) {
            new Thread(){
                public void run() {
                    try {
                        super.sleep(10000);
                        System.out.println(ThreadGenerator.count++);
                    } catch (Exception e) {
                        
                    }
                }
            }.start();
        }
        System.out.println("done");
    }
}

一時的にスレッド生成後にタスクマネージャが示すスレッドは+3000とかなり,メモリの使用量もそれなりに増加するけれども,それぞれ10秒間のSleep後のスレッド終了後はちゃんとスレッドが終了している.OSやJVMに問題があるとは思えない.



追記メモ3
JMSを使わないEJBサンプル,JMSの送信は使うが受信は使わないEJBサンプルで実験した結果,問題個所無し.消去法でJMSの受信のところが原因と推定.

追記メモ4
あった!close()し忘れ・・・(T_T
close()を追加したことでスレッドが残ってしまう現象は解消.
しかし,,,ハンドル数が負荷テストが終わっても初期値に戻らないのは何故.
もうちょいだっ!

追記メモ5
なんとか落ち着いてきた.こんなアプリ構成でやってます.

[処理A]
クライアントAがJBoss1のEJB(A1, Session Bean)を呼び出す
  →EJB(A1)はEJB(A2, Session Bean)を呼び出す→EJB(A2)はJBoss2のJBossMQへメッセージ送信する
  →EJB(A1)はEJB(A3, Entity Bean)を呼び出す→EJB(A3)はMySQLへ1行追加
[処理B]
クライアントBがJBoss1のEJB(B1, Session Bean)を呼び出す
  →EJB(B1)はEJB(B2, Session Bean)を呼び出す→EJB(B2)はJBoss2のJBossMQへメッセージ受信しにいく
  →EJB(B1)はEJB(B3, Entity Bean)を呼び出す→EJB(B3)はMySQLへ1行追加

EJB(B2)のJBossMQへの呼び出しはブロック付きreceiveメソッド呼び出しをしているので,全体としては処理Aと処理Bは繋がっているけれどもJBossMQが間に入って非同期処理となっている.
Eclipse上のJavaクラスがクライアントAおよびクライアントBのクラスをそれぞれ複数スレッド起動させて同時に走らせる.スループットが「処理A>処理B」だとJBossMQのキューにメッセージが時間とともにガンガン貯まってしまうので,スループットは「処理A<=処理B」となるようにスレッド数を調節している.要するにこれを長時間負荷をかけたかったのだけどcloseし忘れなどでメモリがリークしていたわけで・・.

まあ最終的にはこれを処理A・BごとにXAを使って2フェーズコミットの実験をしたいのですが(MySQL5.0系の最新版とConnector/J 3.2の組み合わせならXAを試すことができるので).

とりあえずこんな感じのところまで来ました(常に値が変化するので大雑把).5000トランザクションを処理Aのクライアント2スレッド,処理Bのクライアント10スレッドにて.

[JBoss起動前]
<全体>
ハンドル 12116
スレッド 360
プロセス 51
コミットチャージ 443644

[JBoss1およびJBoss2起動後]
<全体>
ハンドル 14153
スレッド 461
プロセス 55
コミットチャージ 800624
<JBoss1>
ハンドル 963
スレッド 62
仮想メモリ 173708
<JBoss2>
ハンドル 916
スレッド 38
仮想メモリ 170412

[負荷かけ始めて1分以上経過したどこかの時点(メモリ消費最大近辺)]
<全体>
ハンドル 34749
スレッド 3438
プロセス 56
コミットチャージ 1014376
<JBoss1>
ハンドル 16247
スレッド 2919
仮想メモリ 334032
<JBoss2>
ハンドル 2343
スレッド 48
仮想メモリ 170668

[負荷かけ終了してしばらく後]
<全体>
ハンドル 19499
スレッド 466
プロセス 56
コミットチャージ 822252
<JBoss1>
ハンドル 4762
スレッド 64
仮想メモリ 184660
<JBoss2>
ハンドル 2276
スレッド 40
仮想メモリ 171896

[JBoss停止後]
<全体>
ハンドル 12253
スレッド 359
プロセス 52
コミットチャージ 452128

ほとんど問題なしとなったようです.スループットも毎秒23トランザクション(毎分1380トランザクション)でてました.

GCのログを見ていたらMAXの128MBまでにはこれだと最期の方にならないと達していなかったので合計トランザクションを10000に増やして再実験しました.開始から終了まで500秒くらいの負荷テストになりますが,FullGCの頻度がちょっと増したくらいで特に変なところは見当たらず.むしろ300秒経過くらいになるとJBoss1のスレッド数が3500から2000位にまで低下してきて,全体のコミットチャージも950MBくらいに下がっていい感じでした.スループットは毎秒19トランザクション(毎分1140トランザクション)とちょっと落ちてしまいましたが,当初想定した毎分1000トランザクションがとりあえず維持できればOKなので.

というか負荷かけ側のスレッド数を増やすとスループットもあがるので,単にちゃんとマシン用意してしかるべき設定数にすればスループットは現時点では全く問題なしですな.ある環境をシミュレートするため,EJB側に無理やりSleepさせて応答時間を長くするコードをこの後突っ込むつもりではありますが.



追記メモ6
6/4現在,JBossMQのデータソースをHSQLDBに変えたせいなのか,大量のスレッド生成が起こらなくなっている.もしかして非同期じゃなくなっている?