JavaのIntrinsic Locksの動きをbpftraceで確認してみる #Java

概要

JavaにはIntrinsic Locksという仕組がある。オブジェクトごとにそれぞれの固有ロック（Monitor Lock）がつけられて、synchronizedというキーワードだけで楽なマルチスレッド並行処理が実現できる。では、プログラムが実行しているとき、スレッドたちはどうのように協同しているのか？今回は bpftrace を利用して、これを確認してみる。

作業環境

OSはUbuntu 20.04にします。

OpenJDK 14

JDKのDtrace機能必要ですから、ソースからビルトします。

$ apt-get update
$ DEBIAN_FRONTEND=noninteractive ln -fs /usr/share/zoneinfo/Asia/Shanghai /etc/localtime && apt-get install -y tzdata && dpkg-reconfigure --frontend noninteractive tzdata
$ apt-get install build-essential autoconf systemtap-sdt-dev libx11-dev libxext-dev libxrender-dev libxrandr-dev libxtst-dev libxt-dev libcups2-dev libfontconfig1-dev libasound2-dev unzip zip ccache -y

## clone source and boot jdk
$ mkdir jdk && cd jdk
$ git clone https://github.com/openjdk/jdk14u.git

$ wget https://download.java.net/java/GA/jdk13.0.2/d4173c853231432d94f001e99d882ca7/8/GPL/openjdk-13.0.2_linux-x64_bin.tar.gz
$ tar xvf openjdk-13.0.2_linux-x64_bin.tar.gz

$ cd jdk14u

$ bash configure --enable-debug --with-jvm-variants=server --enable-dtrace --with-boot-jdk=../jdk-13.0.2 --enable-ccache
$ make images

$ export JAVA_HOME=$PWD/build/linux-x86_64-server-fastdebug/jdk

bcc と bpftrace

## bcc
$ apt-get install -y linux-headers-$(uname -r) bison build-essential cmake flex g++ git libelf-dev zlib1g-dev libfl-dev systemtap-sdt-dev binutils-dev llvm-8-dev llvm-8-runtime libclang-8-dev clang-8 arping netperf iperf3 python3-distutils
$ git clone --recurse-submodules https://github.com/iovisor/bcc.git
$ mkdir bcc/build; cd bcc/build
$ cmake -DPYTHON_CMD=python3 ..
$ make -j8 && make install && ldconfig

$ cd ../..

## bpftrace

$ git clone https://github.com/iovisor/bpftrace.git
$ mkdir bpftrace/build; cd bpftrace/build

$ cmake -DHAVE_BCC_PROG_LOAD=ON -DHAVE_BCC_CREATE_MAP=ON -DBUILD_TESTING=OFF ..
$ make -j8 && make install

サンプルプログラムを用意

さて、こちらのjavaプログラムを用意します。やっていることはただ二つの競合スレットを呼び出すことです。

Test.java

public class Test {

    private static synchronized void enter(String name) {
        try {
            System.out.println("enter " + name);
            Thread.sleep(1000);
            System.out.println("exit " + name);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

    public static void main(String[] args) {
        new Thread(() -> enter("foo"), "foo").start();
        new Thread(() -> enter("bar"), "bar").start();
    }
}

コンパイルする

$ $JAVA_HOME/bin/javac Test.java

実行と結果

まずは別のターミナルでこのbpftraceコマンドを起動して、トレースを準備する

$ bpftrace - <<EOF
BEGIN { printf("%-12s %-6s %-27s %s\n", "TIME", "TID", "ACTION", "DESC"); }

usdt:$JAVA_HOME/lib/server/libjvm.so:hotspot:thread__start { printf("%-12ld %-6d %-27s", elapsed, arg2, "start");printf("name=%s\n", str(arg0)); }
usdt:$JAVA_HOME/lib/server/libjvm.so:hotspot:thread__stop { printf("%-12ld %-6d %-27s", elapsed, arg2, "stop");printf("name=%s\n", str(arg0)); }

usdt:$JAVA_HOME/lib/server/libjvm.so:hotspot:monitor__contended__enter { printf("%-12ld %-6d %-27s", elapsed, arg0, "monitor_contended_enter"); printf("monitor=0x%lx, class=%s\n", arg1, str(arg2)); }
usdt:$JAVA_HOME/lib/server/libjvm.so:hotspot:monitor__contended__entered { printf("%-12ld %-6d %-27s", elapsed, arg0, "monitor_contended_entered"); printf("monitor=0x%lx, class=%s\n", arg1, str(arg2)); }
usdt:$JAVA_HOME/lib/server/libjvm.so:hotspot:monitor__contended__exit { printf("%-12ld %-6d %-27s", elapsed, arg0, "monitor_contended_exit"); printf("monitor=0x%lx, class=%s\n", arg1, str(arg2)); }
EOF

Attaching 6 probes...

次は先のjavaのプログラムを実行します

$ $JAVA_HOME/bin/java -XX:+ExtendedDTraceProbes  Test
enter bar
exit bar
enter foo
exit foo

二つのスレットは順番に実行しました。では、トレースの方はどうですか。

Attaching 6 probes...
TIME         TID    ACTION                      DESC
3568183750   2      start                      name=Reference Handler
3568644123   3      start                      name=Finalizer
3581708591   1      monitor_contended_exit     monitor=0x7f7314003100, class=java/lang/Object����
3583984755   4      start                      name=Signal Dispatcher
3584404128   6      start                      name=C2 CompilerThread0
3584475441   5      start                      name=Service Thread
3584812927   7      start                      name=C1 CompilerThread0
3585382491   8      start                      name=Sweeper thread
3618900047   9      start                      name=Common-Cleaner
4170272484   2      monitor_contended_exit     monitor=0x7f7314005100, class=java/lang/ref/ReferenceQueue$Lock���#
4176664886   10     start                      name=Notification Thread
4201863620   11     start                      name=foo
4202328663   12     start                      name=bar
4203255448   11     monitor_contended_enter    monitor=0x7f7314007000, class=java/lang/Class�����
5229989467   12     monitor_contended_exit     monitor=0x7f7314007000, class=java/lang/Class�����
5230226530   11     monitor_contended_entered  monitor=0x7f7314007000, class=java/lang/Class�����
5230593438   12     stop                       name=bar
6242293321   11     stop                       name=foo
6247012424   4      stop                       name=Signal Dispatcher

ここでわかるのは、いくつのJVM Systemスレットが起動してから、fooとbarのスレットも起動しました。そして、fooがmonitor_contended_enterの状態になりました、その原因はもちろんbar先に critical region に入りましたから。その後、barがmonitor_contended_exitになって、critical regionを退出。すぐにfooもmonitor_contended_enteredになって、実行が開始しました。

まとめ

簡単な応用例ですが、bpftrace あるいは bcc はすごく強力なツールです、これから他の可能性をもっと発掘て行きたいと思います。

参考資料

JVM Internals