メモリ使用量の増大(解決済み)
メモリ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に変えたせいなのか,大量のスレッド生成が起こらなくなっている.もしかして非同期じゃなくなっている?