Hatena::ブログ(Diary)

techlog RSSフィード

理解というものは、つねに誤解の総体に過ぎない
 「スプートニクの恋人」とか「かえるくん、東京を救う 」より

こちらになりました → http://sadah.hatenablog.com/

2008-07-23

[][][]MacでVisualVMを使う

VisualVMはRCのときWindowsで使ってみたけど、Macには入れていなかった。

というわけでいれてみた。

ダウンロード

VisualVMのサイトから最新のVisualVM 1.0をダウンロードする。


インストール

zipを適当なところに解凍する。


起動失敗

visualvm/bin/visualvm を起動する。

デフォルトのJDKで1.5だと怒られる。

f:id:j7400157:20080723231505p:image

JDK1.6(Java on Mac OS X v10.5 Update 1)はインストール済みだ。

というわけで、visualvmファイルを読んでみると、 visualvm/etc/visualvm.conf でJDKの設定ができるっぽい。

11行目の jdkhome を修正した。

#jdkhome="/path/to/jdk"
jdkhome="/System/Library/Frameworks/JavaVM.framework/Versions/1.6.0/Home"

起動成功

visualvm/bin/visualvm を起動する。

f:id:j7400157:20080723231506p:image

動いた。これでいろいろ楽しめる。

2007-07-18

[][]JMeterはサーバで使おう

JMeterの主な用途は、やっぱり負荷テストツールだろう。

実はそれ以外でも使える場面がいろいろあるが、これはまたいつか。


JMeterに限らず、PCにインストールして使う負荷テストツールの問題は、クライアントがネックになってしまうこと。

数万単位での負荷を掛けるのが難しいこと。

JMeterで100スレッド立ち上げると、かなりPCが不安定になる。

僕のマシンのスペックはWinXP/2.8GHz/1024MB。悪くはない。


Windowsの場合、各種設定はjmeter.batでできる。

初期状態でJMeterのHeapは-Xmx256mとなっているので、512mにチューニングしてみた。

それでも100スレッドくらいが限界。

オプションに -Xloggc:gc.log -XX:+PrintGCDetails を追加してGCViewerで確認したが、メモリがネックというわけではなさそう。

タスクマネージャでCPUを見ても、そこまでクライアントが高負荷になっているわけではない。

Javaが入っていれば、JMeterはファイルを置くだけで実行できる。


ちゃんとした負荷評価が必要なシステム(高負荷に耐える必要のあるシステム)って、APサーバは複数台設置されていることが多い。

システム全体に負荷を掛けることも大切だけど、これは難しいことが多い。

1サーバの性能を評価する方向に持っていって、使わないサーバから負荷を掛ければいい。

これは以前どこかで、HPのなかの人がJMeterについて発表されていた内容。


負荷テストのフェーズは、プロジェクトの最後になることが多いと思う。

でも負荷テストは難しいし、大変。制約条件の多いなかでテストしなくてはならない。

JMeterが選択肢のひとつにあれば、大分幅が広がると思う。

サーバが使えなくて、クライアントを大量に用意しなくてはならない場合も、少なくともライセンス費用は考えなくて済む。


ばりばり業務系の複雑なシステムを評価する目的だと、JMeterは使い辛いかもしれない。

向いていないわけではないし、ちゃんとシナリオを作ればできる。

ただし機能の問い合わせはできないし、GUIはやっぱりちょっと貧弱だし、サポートがないので敷居が高いのかもしれない。

でもJMeterを使ったほうが良い場面もたくさんあると思う。

今後も積極的に使っていきたい。


参考

JMeter

2007-07-17

[][]vmstatをみる

vmstatグラフ化君でグラフ化して、確認している。

便利すぎて、これ無しでvmstatなんて見る気になれない。

vmstatはけっこう不便。

  • タイムスタンプがでてこない
  • distributionによって、項目が異なる
  • いろんな情報が取れるけど、まとめにくい

vmstatグラフ化君はExcelでマクロを使っている。

  • 開始時刻を入れて時系列のグラフができる
  • 監視間隔が指定できる
  • telnetのログを使って、リアルタイム監視できる
  • 複数の表示項目に対応している

ログを食わせて、グラフができたら、報告書に貼り付ければいい。

作者さんのサイトにいろんなグラフ化君がいる。Excelはすごい。

2007-07-16

[][]GCをみる

GCの動きを見たいときは -Xloggc:<file> や -XX:+PrintGCDetails をつけて、GCViewer で見ていた。

これは時系列でのGCの動きや、メモリの推移を知るには便利だけど、細かい動きについては解り辛い。概要を知るには便利だけど、細かく知りたい時は不便という感じ。

# 使いこなせていないだけかもしれないけど。

GCが起きるメモリリークプログラムをさくっと書いてみる。

import java.util.List;
import java.util.ArrayList;

public class GCTest {
	public static void main(String[] args){
		List<String> list = new ArrayList<String>();
		
		for(;;){
			String str = new String("hoge");
			list.add(str);
		}
	}
}

こいつを以下のオプションをつけて実行する。

-Xloggc:<file>
-XX:+PrintGCDetails

実行すると、OutOfMemoryErrorが起きる。

> java -Xloggc:gc.log -XX:+PrintGCDetails GCTest
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space

こんな感じのログがでてくる。

1.831: [GC 1.831: [DefNew: 4096K->4096K(4544K), 0.0000118 secs]1.831: [Tenured: 56595K->60544K(60544K), 0.2608705 secs] 60691K->60689K(65088K), 0.2610212 secs]
2.097: [Full GC 2.097: [Tenured: 60544K->60544K(60544K), 0.2638188 secs] 62056K->61982K(65088K), [Perm : 262K->262K(8192K)], 0.2639318 secs]
2.361: [Full GC 2.361: [Tenured: 60544K->60544K(60544K), 0.2532709 secs] 61982K->61982K(65088K), [Perm : 262K->262K(8192K)], 0.2533446 secs]

最後のほうで、FullGCが走っている。でもメモリ領域は全然開放されていない。


メモリリークを確認するだけなら、上記のログで問題ないかもしれない。

でもメモリチューニングをするには、ちょっと足りない。

全体のサイズ、NewとOldのサイズ、EdenとSurvivorの比率なんかを決めなきゃいけないけど、さっぱりわからない。


というわけで、いろいろオプションを追加してみる。

-Xloggc:/tmp/gc.log
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintHeapAtGC
-XX:+PrintTenuringDistribution
-XX:+TraceGen0Time
-XX:+TraceGen1Time

だんだんコマンドが長くなる。

> java -Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:+TraceGen0Time -XX:+TraceGen1Time GCTest
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
[Accumulated GC generation 0 time 0.4289908 secs, 39 GC's, avg GC time 0.0109998]
[Accumulated GC generation 1 time 2.0735346 secs, 14 GC's, avg GC time 0.1481096]

でてくるログはこれ。

2.000: [GC {Heap before gc invocations=38:
 def new generation   total 4544K, used 4096K [0x22bd0000, 0x230b0000, 0x230b0000)
  eden space 4096K, 100% used [0x22bd0000, 0x22fd0000, 0x22fd0000)
  from space 448K,   0% used [0x22fd0000, 0x22fd0000, 0x23040000)
  to   space 448K,   0% used [0x23040000, 0x23040000, 0x230b0000)
 tenured generation   total 60544K, used 56595K [0x230b0000, 0x26bd0000, 0x26bd0000)
   the space 60544K,  93% used [0x230b0000, 0x267f4c58, 0x267f4e00, 0x26bd0000)
 compacting perm gen  total 8192K, used 262K [0x26bd0000, 0x273d0000, 0x2abd0000)
   the space 8192K,   3% used [0x26bd0000, 0x26c11b08, 0x26c11c00, 0x273d0000)
    ro space 8192K,  63% used [0x2abd0000, 0x2b0dd860, 0x2b0dda00, 0x2b3d0000)
    rw space 12288K,  46% used [0x2b3d0000, 0x2b970728, 0x2b970800, 0x2bfd0000)
2.001: [DefNew: 4096K->4096K(4544K), 0.0000103 secs]2.001: [Tenured: 56595K->60544K(60544K), 0.2871982 secs] 60691K->60689K(65088K)Heap after gc invocations=39:
 def new generation   total 4544K, used 145K [0x22bd0000, 0x230b0000, 0x230b0000)
  eden space 4096K,   3% used [0x22bd0000, 0x22bf4660, 0x22fd0000)
  from space 448K,   0% used [0x22fd0000, 0x22fd0000, 0x23040000)
  to   space 448K,   0% used [0x23040000, 0x23040000, 0x230b0000)
 tenured generation   total 60544K, used 60544K [0x230b0000, 0x26bd0000, 0x26bd0000)
   the space 60544K, 100% used [0x230b0000, 0x26bd0000, 0x26bd0000, 0x26bd0000)
 compacting perm gen  total 8192K, used 262K [0x26bd0000, 0x273d0000, 0x2abd0000)
   the space 8192K,   3% used [0x26bd0000, 0x26c11b08, 0x26c11c00, 0x273d0000)
    ro space 8192K,  63% used [0x2abd0000, 0x2b0dd860, 0x2b0dda00, 0x2b3d0000)
    rw space 12288K,  46% used [0x2b3d0000, 0x2b970728, 0x2b970800, 0x2bfd0000)
}
, 0.2874919 secs]
2.292: [Full GC {Heap before gc invocations=39:
 def new generation   total 4544K, used 1512K [0x22bd0000, 0x230b0000, 0x230b0000)
  eden space 4096K,  36% used [0x22bd0000, 0x22d4a0f8, 0x22fd0000)
  from space 448K,   0% used [0x22fd0000, 0x22fd0000, 0x23040000)
  to   space 448K,   0% used [0x23040000, 0x23040000, 0x230b0000)
 tenured generation   total 60544K, used 60544K [0x230b0000, 0x26bd0000, 0x26bd0000)
   the space 60544K, 100% used [0x230b0000, 0x26bd0000, 0x26bd0000, 0x26bd0000)
 compacting perm gen  total 8192K, used 262K [0x26bd0000, 0x273d0000, 0x2abd0000)
   the space 8192K,   3% used [0x26bd0000, 0x26c11b08, 0x26c11c00, 0x273d0000)
    ro space 8192K,  63% used [0x2abd0000, 0x2b0dd860, 0x2b0dda00, 0x2b3d0000)
    rw space 12288K,  46% used [0x2b3d0000, 0x2b970728, 0x2b970800, 0x2bfd0000)
2.293: [Tenured: 60544K->60544K(60544K), 0.2792200 secs] 62056K->61982K(65088K), [Perm : 262K->262K(8192K)]Heap after gc invocations=40:
 def new generation   total 4544K, used 1438K [0x22bd0000, 0x230b0000, 0x230b0000)
  eden space 4096K,  35% used [0x22bd0000, 0x22d37940, 0x22fd0000)
  from space 448K,   0% used [0x22fd0000, 0x22fd0000, 0x23040000)
  to   space 448K,   0% used [0x23040000, 0x23040000, 0x230b0000)
 tenured generation   total 60544K, used 60544K [0x230b0000, 0x26bd0000, 0x26bd0000)
   the space 60544K, 100% used [0x230b0000, 0x26bd0000, 0x26bd0000, 0x26bd0000)
 compacting perm gen  total 8192K, used 262K [0x26bd0000, 0x273d0000, 0x2abd0000)
   the space 8192K,   3% used [0x26bd0000, 0x26c11b08, 0x26c11c00, 0x273d0000)
    ro space 8192K,  63% used [0x2abd0000, 0x2b0dd860, 0x2b0dda00, 0x2b3d0000)
    rw space 12288K,  46% used [0x2b3d0000, 0x2b970728, 0x2b970800, 0x2bfd0000)
}
, 0.2795012 secs]
2.572: [Full GC {Heap before gc invocations=40:
 def new generation   total 4544K, used 1438K [0x22bd0000, 0x230b0000, 0x230b0000)
  eden space 4096K,  35% used [0x22bd0000, 0x22d37940, 0x22fd0000)
  from space 448K,   0% used [0x22fd0000, 0x22fd0000, 0x23040000)
  to   space 448K,   0% used [0x23040000, 0x23040000, 0x230b0000)
 tenured generation   total 60544K, used 60544K [0x230b0000, 0x26bd0000, 0x26bd0000)
   the space 60544K, 100% used [0x230b0000, 0x26bd0000, 0x26bd0000, 0x26bd0000)
 compacting perm gen  total 8192K, used 262K [0x26bd0000, 0x273d0000, 0x2abd0000)
   the space 8192K,   3% used [0x26bd0000, 0x26c11b08, 0x26c11c00, 0x273d0000)
    ro space 8192K,  63% used [0x2abd0000, 0x2b0dd860, 0x2b0dda00, 0x2b3d0000)
    rw space 12288K,  46% used [0x2b3d0000, 0x2b970728, 0x2b970800, 0x2bfd0000)
2.572: [Tenured: 60544K->60544K(60544K), 0.2868222 secs] 61982K->61982K(65088K), [Perm : 262K->262K(8192K)]Heap after gc invocations=41:
 def new generation   total 4544K, used 1438K [0x22bd0000, 0x230b0000, 0x230b0000)
  eden space 4096K,  35% used [0x22bd0000, 0x22d37940, 0x22fd0000)
  from space 448K,   0% used [0x22fd0000, 0x22fd0000, 0x23040000)
  to   space 448K,   0% used [0x23040000, 0x23040000, 0x230b0000)
 tenured generation   total 60544K, used 60544K [0x230b0000, 0x26bd0000, 0x26bd0000)
   the space 60544K, 100% used [0x230b0000, 0x26bd0000, 0x26bd0000, 0x26bd0000)
 compacting perm gen  total 8192K, used 262K [0x26bd0000, 0x273d0000, 0x2abd0000)
   the space 8192K,   3% used [0x26bd0000, 0x26c11b08, 0x26c11c00, 0x273d0000)
    ro space 8192K,  63% used [0x2abd0000, 0x2b0dd860, 0x2b0dda00, 0x2b3d0000)
    rw space 12288K,  46% used [0x2b3d0000, 0x2b970728, 0x2b970800, 0x2bfd0000)
}
, 0.2870730 secs]

最初のログと同様、最後の3回のGCログ。大量発生。

でもこれすごく便利。

GC前後のメモリ領域がわかる。

各領域の使用量がわかる。

Permanent領域の使用量がわかる。

最初に追加したログ出力オプションと比較しても、オーバヘッドがあまりないような気がする。

これだけわかれば、チューニングもしやすい。

このログを tail -f で見てると、眠くなるけどなんとなく問題がわかってくる。

これだと、FullGCが起きてもメモリ領域が開放されていない。

オブジェクトの開放漏れがあったり、Heapが小さすぎるのかもしれない。あるいはNew領域が小さくてScavenge GCがすぐに発生してしまい、Old領域を圧迫しているかもしれない。

# このサンプルプログラムだと開放漏れだけど。


GCViewerでGCの発生状況を確認して、ポイントを絞ってオプションを追加して詳細を調べる。

これはなかなかいい感じ。


恥ずかしながら、今回初めてしった事実。-Xloggc:<file> と -verbose:gc で出てくるログって、同じものだったんだ・・・。後者のほうが、詳細なのかと思ってた・・・。


参考

ガベージコレクタをビジュアライズ GCViewer - メモリリーク発見にも

@IT - Webアプリの問題点を「見える化」する7つ道具

@IT - チューニングのためのJavaVM講座(前編)

@IT - Javaのヒープ・メモリ管理の仕組み

SMG - -verbose:gcで出力される情報がたりません。

SMG - HPROFによるJavaプロファイリング


<追記>

最近ではこの本がでて、解析の仕方やツールの使い方ががっつり書いてあっていい感じ。

現場で使えるデバッグ & トラブルシュート Java編
小堀 一雄 茂呂 範 佐藤 聖規 石垣 一 飯山 教史
翔泳社
売り上げランキング: 40179

2007-06-18

[][][]パフォーマンスチューニングBlog

この会社のblogすごい。blogが企業サイトになっている。内容もすごそう。

気になるタイトルがたくさんある。

tomcat6とcometのこと

Apacheパフォーマンスチューニング

keep-aliveのことをちゃんと考える

ブラウザでHTTP通信をトレースする

来月はチューニング系の仕事をするので、暇を見てちゃんと読んでみよう。