読者です 読者をやめる 読者になる 読者になる

HHeLiBeXの日記 正道編

日々の記憶の記録とメモ‥

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 2 SE 5.0 Update 22 (Sun製)
  • Java SE 6 Update 17 (Sun製)
  • Java 2 SE 5.0 (SR10) (IBM製)

動作としては基本的にどれも同じなので、「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の発生を抑えようとする努力が、逆に悲劇を巻き起こす可能性があることがわかる。