OpenJDK開発記：JDK-8249720: Generated bytecodes of EventWriter don't be output to the logを直してみた。

これは何？

今回、パッチを書いたのはJDK-8249720のGenerated bytecodes of EventWriter don't be output to the logです。

[JDK-8249720] Generated bytecodes of EventWriter don't be output to the log - Java Bug System

VM起動引数に-Xlog:jfr+system+bytecode=traceを付けてJFRを実行すると、JFRの中で動的に作成されて使用されるEventWriterが生成されたときに、そのクラスのオペコードをログに出力する機能があります。 たまたまその機能を使ってバイトコードの変化を探してたらこのバグを発見しました。 OpenJDK の 15 からそれがデグレにより出力されなくなったため、それを修正しました。

どんな実装だったのか

原因としては、JFR のログ出力周りのオーバーヘッドを減らすという修正が入ったときに、修正ミスによってログが出力されなくなってしまいました。

-        Logger.log(LogTag.JFR_SYSTEM_BYTECODE, LogLevel.TRACE, () -> {
+        if (Logger.shouldLog(LogTag.JFR_SYSTEM_BYTECODE, LogLevel.TRACE)) {
            ClassReader cr = new ClassReader(bytes);
            ByteArrayOutputStream baos = new ByteArrayOutputStream();
            PrintWriter w = new PrintWriter(baos);
            w.println("Bytecode:");
            cr.accept(new TraceClassVisitor(w), 0);
-            return baos.toString();
-        });
+        };

以前の実装では、最後の行のreturn baos.toString();がロガーに渡されてログを出力していました。これを消してしまったためログが出なくなっています。

8247320: JFR: Reduce logging overhead · openjdk/jdk@65c461e · GitHub

どう直したの？

単純にログを出力する行を足しただけです。それに加えて、もうデグレしないようにテストケースを追加しています。

パッチはこちら

パッチの抜粋はこちらです。

--- old/src/jdk.jfr/share/classes/jdk/jfr/internal/ASMToolkit.java   2020-07-19 21:31:04.125291400 +0900
+++ new/src/jdk.jfr/share/classes/jdk/jfr/internal/ASMToolkit.java    2020-07-19 21:31:03.955544600 +0900
@@ -155,6 +155,7 @@
             PrintWriter w = new PrintWriter(baos);
             w.println("Bytecode:");
             cr.accept(new TraceClassVisitor(w), 0);
+            Logger.log(LogTag.JFR_SYSTEM_BYTECODE, LogLevel.TRACE, baos.toString());
         };
     }
 
--- /dev/null 2020-07-19 21:20:25.577740400 +0900
+++ new/test/jdk/jdk/jfr/jvm/TestEventWriterLog.java  2020-07-19 21:31:05.847842600 +0900
@@ -0,0 +1,44 @@
+ * @test TestEventWriterLog
+ * @summary Test that log message of JFR when handle bytecodes
+ * @key jfr
+ * @requires vm.hasJFR
+ * @library /test/lib /test/jdk
+ * @run main/othervm TestEventWriterLog
+ */
+
+import jdk.test.lib.process.ProcessTools;
+import jdk.test.lib.process.OutputAnalyzer;
+
+public class TestEventWriterLog {
+    public static void main(String[] args) throws Exception {
+        ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-Xlog:jfr+system+bytecode=trace", "-XX:StartFlightRecording", "-version");
+        OutputAnalyzer output = new OutputAnalyzer(pb.start());
+        output.shouldContain("extends jdk/jfr/internal/handlers/EventHandler");
+    }
+}

Java のメモリ上にあるバイトコードをクラスファイルとして出力

開発者は Java 言語でソースコードを書き、そのソースコードは Javac というコンパイラでバイトコードに変換されクラスファイルとなり、クラスファイルは Jar ファイルとしてまとめられ、 Java コマンドでアプリケーションとして実行します。

アプリケーション上で実行されるバイトコードはコンパイルされたものと一緒であることが普通です。ASM などのバイトコードを操作するツールなど一部のフレームワークや Java の機能を使うと、このバイトコードは変更されます。操作結果を確認したい場合などそのバイトコードを見たいことは多々あると思いますので、取り出す方法を紹介します。

手順

取り出すためには JVM のデバッガである jhsdb というツールを使います。これは JDK に標準で含まれているツールです。javaコマンドと一緒に$JAVA_HOME/binに含まれています。これにhsdbという引数を付けて実行することでツールをGUIで起動します。

$ jhsdb hsdb

デバッグをする方法は、プロセスへの接続、コアファイルを与えるなどいろいろあります。今回はプロセスIDを指定してプロセスへ接続します。 [File] - [Attach to HotSpot Process... Alt-A] を実行します。

接続したいアプリケーションのプロセスIDを取得します。これはjhsdbと同じく Java に標準で含まれる jcmd を使うのが良いでしょう。これも$JAVA_HOME/binに含まれています。以下の様に実行すると、プロセスID と実行しているクラスが表示されます。今回はSampleApplicationへ接続しますのでプロセスIDは 82884 になります。

$ jcmd
82884 SampleApplication
157688 jdk.jcmd/sun.tools.jcmd.JCmd
75868 jdk.hotspot.agent/sun.jvm.hotspot.SALauncher hsdb

プロセスID を入力して[OK]を押すとそのプロセスへ接続します。接続が完了すると、以下の様に JVM で動いているスレッドの一覧が表示されます。

今回の目的はクラスファイルを得ることです。その役割である JVM 上にロードされているクラスを見るクラスブラウザを起動しましょう。[Tools] - [Class Browser] を選択します。

クラスブラウザが起動すると、JVM に読み込まれているクラスが一覧で表示されます。上の方にあるテキストフィールドに取得したいクラス名を入力することで絞ることができます。取得したいクラスが見つかったらそのクラス名をクリックします。

クラスをクリックすると、そのクラスのスーパークラス、フィールド、メソッド、コンスタントプールの一覧が表示されます。 また、上の方にはクラスファイルを出力するためのCreate .class Fileがあります。これをクリックすることでクラスファイルが出力されます。

出力先はjhsdbを起動しているディレクトリ直下です。パッケージ構造をディレクトリとした形で出力されます。移行した画面に表示されているクラス名を選択すると先ほどの画面に戻れます。

得られたクラスファイルは JD や IntelliJ に含まれているデコンパイラを使うことで開けます。注意したいのはフィールドやメソッドを自動生成したことを示す ACC_SYNTHETIC というフラグです。デコンパイラによってはこのフラグがあるフィールドやメソッドを無視する事もあるので注意してください。

JFR Under the hood : JFRイベントの書き込み -Java編-

結論

C/C++ 側で Java のjdk.jfr.internal.EventWriterが作成されます。このインスタンスにはThreadLocalに作られたJava用のバッファへのポインタを保持しています。イベントが書込まれるとEventWriterはそのイベントをこのバッファへ書込みます。この書き込み処理は各イベントに commit メソッドを使って行われます。このメソッドは親クラスであるEventクラスでは空実装ですが、jdk.jfr.FlightRecorderクラスがイベントを読み込む際にバイトコードを操作されて、commitメソッドはイベントが持っているフィールドを先ほどのバッファに書くように変更されます。

今回はこの様なイベントクラスを使って、その変化を確認していきます。

@Label("JfrEvent")
public class JfrEvent extends Event {

    @Label("id")
    private int id;

    @Label("name")
    private String name;

    public int getId() {
        return id;
    }

    public void setId(int id) {
        this.id = id;
    }

    public String getName() {
        return name;
    }

    public void setName(String name) {
        this.name = name;
    }
}

JFR では、先ほどのイベントクラスを C/C++ レベルで書き換えます。

• @src/hotspot/share/jfr/instrumentation/jfrEventClassTransformer.cpp

またイベントに合わせたイベントハンドラはASM と言うツールを使ってバイトコードを動的に作成します。このイベントハンドラはjdk.jfr.internal.handlers.EventHandlerを継承しています。

• @src/jdk.jfr/share/classes/jdk/jfr/internal/EventHandlerCreator.java
• @src/jdk.jfr/share/classes/jdk/jfr/internal/EventWriterMethod.java

イベントのクラスは以下の様に修正されます。

public class JfrEvent extends Event {
    private int id;
    private String name;
    private static EventHandler eventHandler;
    private transient long startTime;
    private transient long duration;

    public String getName() {
        return this.name;
    }

    public JfrEvent() {
    }

    static {
        FlightRecorder.register(JfrEvent.class);
    }

    public void begin() {
        this.startTime = EventHandler.timestamp();
    }

    public void end() {
        this.duration = EventHandler.duration(this.startTime);
    }

    public void setName(String name) {
        this.name = name;
    }

    public int getId() {
        return this.id;
    }

    public void setId(int id) {
        this.id = id;
    }

    public void commit() {
        if (this.isEnabled()) {
            if (this.startTime == 0L) {
                this.startTime = EventHandler.timestamp();
            } else if (this.duration == 0L) {
                this.duration = EventHandler.timestamp() - this.startTime;
            }

            if (this.shouldCommit()) {
                ((EventHandler1754_1595079330631_153352)eventHandler).write(this.startTime, this.duration, this.id, this.name);
            }

        }
    }

    public boolean isEnabled() {
        return eventHandler.isEnabled();
    }

    public boolean shouldCommit() {
        return eventHandler.shouldCommit(this.duration);
    }
}

また、このイベントクラス用のイベントハンドラは以下の様に作られます。

public final class EventHandler1754_1595079330631-153352 extends EventHandler {
    private final StringPool stringPool3 = this.createStringFieldWriter();

    private EventHandler1754_1595079330631_153352(boolean registered, EventType eventType, EventControl eventControl) {
        super(registered, eventType, eventControl);
    }

    public void write(long startTime, long duration, int id, String name) {
        EventWriter eventWriter;
        try {
            do {
                eventWriter= EventWriter.getEventWriter();
                if (!eventWriter.beginEvent(super.platformEventType)) {
                    break;
                }
                eventWriter.putLong(startTime);
                eventWriter.putLong(duration);
                eventWriter.putEventThread();
                eventWriter.putStackTrace();
                eventWriter.putInt(id);
                eventWriter.putString(name, this.stringPool3);
            } while(!eventWriter.endEvent());
        } catch (Throwable t) {
            EventWriter eventWriter2 = EventWriter.getEventWriter();
            if (eventWriter2 != null) {
                eventWriter2.reset();
            }
            throw t;
        }
    }
}