Finalizerの動作を実際に見てみる
次の記事(2007/12/27)：
現場から学ぶWebアプリ開発のトラブルハック（9）：JavaのGC頻度に惑わされた年末年始の苦いメモリ (1/3) - ＠IT
の「【第5話】犯人はお前だ！ Finalizer!!」を久しぶりに目にして、Finalizerの動作を実際に見てみるか、と思ったらしい。
とりあえず、いろいろ試してみたところ、System.gc() メソッドを呼ぶとFull GCが動くようなので、その前提で検証コード。
public class Main { // "#finalize()"を含むメッセージとともにlog(msg)が呼ばれたらtrueになる。 private static boolean finalized = false; public static void main(String[] args) throws InterruptedException { fullGC(); dumpMemoryUsage(); // この処理によって、ヒープの使用量がドンと増える。 sep("start Create Bean-A"); Bean beanA = new Bean() { public String toString() { return "Bean-A@" + hashCode(); } }; log("beanA is created"); sep("end Create Bean-A: " + beanA); dumpMemoryUsage(); fullGC(); dumpMemoryUsage(); // この処理によって、ヒープの使用量がさらにドンと増える。 sep("start Create Bean-B"); Bean beanB = new Bean() { public String toString() { return "Bean-B@" + hashCode(); } protected void finalize() throws Throwable { log(this + "#finalize()"); super.finalize(); } }; log("beanB is created"); sep("end Create Bean-B: " + beanB); dumpMemoryUsage(); fullGC(); dumpMemoryUsage(); // この処理によって、beanA がGC対象となり、次のGCで回収される。 sep("start Dispose Bean-A: " + beanA); beanA = null; log("beanA is set to null"); sep("end Dispose Bean-A"); dumpMemoryUsage(); fullGC(); dumpMemoryUsage(); // この処理によって、beanB はfinalize対象となる。GC対象ではない。 sep("start Dispose Bean-B: " + beanB); beanB = null; log("beanB is set to null"); sep("end Dispose Bean-B"); dumpMemoryUsage(); // beanB のfinalize()が呼ばれるまで待ってみる。 for (int i = 0; !finalized; ++i) { fullGC(); dumpMemoryUsage(); Thread.sleep(500); } // beanB のfinalize()が呼ばれたので、今度はbeanBがGC対象になっているはず。 fullGC(); dumpMemoryUsage(); } private static void log(String fmt, Object... args) { String f = " " + fmt; System.out.printf(f, args); System.err.printf(f, args); } private static void log(String msg) { String m = " " + msg; System.out.println(m); System.err.println(m); if (msg.contains("#finalize()")) { finalized = true; } } private static void sep(String msg) { String sep; if (msg.startsWith("start ")) { sep = ">>--------------"; } else if (msg.startsWith("end ")) { sep = "<<--------------"; } else { sep = "||--------------"; } String m = " " + sep + msg; System.out.println(m); System.err.println(m); } private static void fullGC() { sep("start Full GC"); System.gc(); sep("end Full GC"); } private static void dumpMemoryUsage() { Runtime rt = Runtime.getRuntime(); long max = rt.maxMemory(); long total = rt.totalMemory(); long free = rt.freeMemory(); long used = (total - free); log("max = %7.3f total = %7.3f free = %7.3f used = %7.3f\n", max / 1024.0 / 1024, total / 1024.0 / 1024, free / 1024.0 / 1024, used / 1024.0 / 1024); } }
この中で使用されているクラス Bean は次のような感じ。
public class Bean { private double[] d = new double[1024 * 1024 * 16]; }
配列は別オブジェクトになってしまうため、本当は、プリミティブ型のフィールドを 1024x1024x16 個並べたいのだけど、面倒だったのでこういう形になった。
とりあえず、次のJava VMで実行してみた。
動作としては基本的にどれも同じなので、「Java SE 6 Update 17 (Sun製)」での結果のみを示す。
1: >>--------------start Full GC
2:[Full GC 645K->136K(520256K), 0.0178994 secs]
3: <<--------------end Full GC
4: max = 508.063 total = 508.063 free = 507.299 used = 0.763
5: >>--------------start Create Bean-A
6: beanA is created
7: <<--------------end Create Bean-A: Bean-A@14737862
8: max = 508.063 total = 508.063 free = 379.299 used = 128.763
9: >>--------------start Full GC
10:[Full GC 131853K->131260K(520256K), 0.0178932 secs]
11: <<--------------end Full GC
12: max = 508.063 total = 508.063 free = 379.248 used = 128.814
13: >>--------------start Create Bean-B
14: beanB is created
15: <<--------------end Create Bean-B: Bean-B@19581314
16: max = 508.063 total = 508.063 free = 251.248 used = 256.814
17: >>--------------start Full GC
18:[Full GC 262977K->262332K(520256K), 0.0177688 secs]
19: <<--------------end Full GC
20: max = 508.063 total = 508.063 free = 251.248 used = 256.814
21: >>--------------start Dispose Bean-A: Bean-A@14737862
22: beanA is set to null
23: <<--------------end Dispose Bean-A
24: max = 508.063 total = 508.063 free = 251.248 used = 256.814
25: >>--------------start Full GC
26:[Full GC 262977K->131259K(520256K), 0.1788854 secs]
27: <<--------------end Full GC
28: max = 508.063 total = 508.063 free = 379.249 used = 128.813
29: >>--------------start Dispose Bean-B: Bean-B@19581314
30: beanB is set to null
31: <<--------------end Dispose Bean-B
32: max = 508.063 total = 508.063 free = 379.249 used = 128.813
33: >>--------------start Full GC
34:[Full GC 131904K->131259K(520256K), 0.0184435 secs]
35: <<--------------end Full GC
36: max = 508.063 total = 508.063 free = 379.249 used = 128.813
37: Bean-B@19581314#finalize()
38: >>--------------start Full GC
39:[Full GC 132549K->187K(520256K), 0.0187389 secs]
40: <<--------------end Full GC
41: max = 508.063 total = 508.063 free = 507.249 used = 0.813説明のために行番号をつけた。(行頭のコロン(':')までが追加した部分。)
- 16行目までで、2つの巨大なオブジェクトが生成され、それぞれ約128MBのメモリを使用していることがわかる。
- finalize()メソッドをオーバーライドしていない Bean-A は、参照を切った(22行目)後の最初のFull GC(26行目)で回収されている。
- finalize()メソッドをオーバーライドした Bean-B は、参照を切っても(30行目)、その後のFull GC(34行目)で回収されない。
- Bean-B は、finalize()メソッドが呼ばれた(37行目)後のFull GC(39行目)でようやく回収される。
元の記事にあるように、Full GCの発生を抑えようとする努力が、逆に悲劇を巻き起こす可能性があることがわかる。
