[Java] Check the movement of Intrinsic Locks of Java with bpftrace

2 minute read

Overview

Java has a mechanism called Intrinsic Locks.Eachobjectisgivenitsownlock(MonitorLock),andeasymultithreadedparallelprocessingcanberealizedonlywiththekeywordsynchronized.Sohowdothreadscooperatewhentheprogramisrunning?Thistime,Iwillcheckthisusingbpftrace.

Work environment

The OS is Ubuntu 20.04.

OpenJDK 14

Dtrace function of JDK is required, so build it from the source.

$ 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 and 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

Sample program prepared

Now, prepare this java program. What we’re doing is calling just two competing threats.

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();
    }
}

Compile

$ $JAVA_HOME/bin/javac Test.java

Execution and result

First, start the bpftrace command in another terminal to prepare the trace.

$ 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...

Next, execute the above java program

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

The two threats ran sequentially. So what about tracing?

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=bar4203255448 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

What I can see here is how many JVM System threats started, and then the foo and bar threats also started. Then, foo is in the state of monitor_contended_enter because the reason is, of course, bar ahead in the critical region. After that, bar became monitor_contended_exit and left the critical region. Immediately, foo also became monitor_contended_entered and the execution started.

Summary

It’s a simple application, but bpftrace or bcc is a very powerful tool, and I would like to discover more other possibilities.

Reference materials