Monday, April 7, 2014

JNI and LD_LIBRARY_PATH


Global variables are evil, even if they still appear everywhere, often as environment variables. If you use Tibco on Unix, you have to set LD_LIBRARY_PATH to include the native libraries. Among other things, this complicates using a continuous build server that needs different variables for different builds.

If we remove LD_LIBRARY_PATH and set java.library.path instead, we can load native libraries. But if that loaded library then loads another, it naturally looks for it in LD_LIBRARY_PATH and you get something like:

java.lang.UnsatisfiedLinkError: /opt/mds/tibco_8_1/tibrv/8.1/lib/libtibrvj.so: libtibrvcmq.so: cannot open shared object file: No such file or directory

that is, the first one is loaded but the second one fails as it has not been loaded via the JVM but directly by Linux (which knows nothing about java.library.path).

Taking a look at the dependencies between the native libs looks like this:

> readelf -a /opt/mds/tibco_8_1/tibrv/8.1/lib/libtibrv.so | grep NEEDED
 0x00000001 (NEEDED)                    Shared library: [libc.so.6]
 0x00000001 (NEEDED)                    Shared library: [libpthread.so.0]

So, libtibrv.so just needs standard Linux libraries.

> readelf -a /opt/mds/tibco_8_1/tibrv/8.1/lib/libtibrvcm.so | grep NEEDED
 0x00000001 (NEEDED)                    Shared library: [libtibrv.so.6]
 0x00000001 (NEEDED)                    Shared library: [libc.so.6]

And in turn, libtibrvcm needs libtibrv and so on.

Using readelf we can then build up the dependency tree (more on the ELF format can be found here).

We can programatically get around this by just setting java.library.path and calling java code like this:

System.loadLibrary("tibrv");
System.loadLibrary("tibrvcm");
System.loadLibrary("tibrvft");
System.loadLibrary("tibrvcmq");

This loads the libraries in order. Changing the order causes a java.lang.UnsatisfiedLinkError.

Sunday, March 30, 2014

The Many Faces of Traces


Most Java developers are familiar with jstack but if you're running on Linux, you might want to familiarise yourself with pstack too. This is especially useful if you are executing native code.

Let's create some native code we can call via JNI (see my last post if you want to compile it yourself):

#include <stdlib.h>
#include <stdio.h>
#include <jni.h>
#include "com_henryp_jni_MyJni.h"
#include <execinfo.h>
#include <signal.h>
#include <unistd.h>

JNIEXPORT jstring JNICALL Java_com_henryp_jni_MyJni_munge
  (JNIEnv* env, jobject obj, jstring str) {
        void *array[20];
        size_t size;
        jstring ret = 0;
        char* msg = "this is a test";

        printf("Java_com_henryp_jni_MyJni_munge called!\n");
        ret = (*env)->NewStringUTF(env, msg);

        printf("Hit return...\n");
        getchar();

        // get void*'s for all entries on the stack
        size = backtrace(array, 20);
        // print out all the frames to stderr
        backtrace_symbols_fd(array, size, STDERR_FILENO);

        return ret;
}

Here, we enter the C code, wait for a key press and print to stderr the non-Java stack trace by calling backtrace. This outputs:

[phenry@localhost MyTest]$ java -Djava.library.path=/mnt/hgfs/Shared/Code/JNI/MyJni/Debug -cp target/classes/ com.henryp.jni.MyJni
Java_com_henryp_jni_MyJni_munge called!
Hit return...

/mnt/hgfs/Shared/Code/JNI/MyJni/Debug/libMyJni.so(Java_com_henryp_jni_MyJni_munge+0x61)[0x1b7569]
[0xb560a84d]
[0xb560345a]
[0xb56003d9]
/usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so(+0x27dd65)[0x885d65]
/usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so(+0x3a27d9)[0x9aa7d9]
/usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so(+0x27cb7f)[0x884b7f]
/usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so(+0x29062a)[0x89862a]
/usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so(+0x29ae9b)[0x8a2e9b]
/usr/java/jdk1.7.0_07/bin/../jre/lib/i386/jli/libjli.so(+0x3384)[0x116384]
/lib/libpthread.so.0[0x468a4a2e]
/lib/libc.so.6(clone+0x5e)[0x467ea81e]
this is a test

If we allow the thread to tarry a little a little in this native method and run jstack we see our thread is runnable in the Java world even though it is blocking in the real world.

"main" prio=10 tid=0xb7705800 nid=0x3d46 runnable [0xb78a8000]
   java.lang.Thread.State: RUNNABLE
at com.henryp.jni.MyJni.munge(Native Method)
at com.henryp.jni.MyJni.main(MyJni.java:22)

This is consistent with what RUNNABLE means in the Java world, name that it is "in the runnable state is executing in the Java virtual machine but it may be waiting for other resources from the operating system such as processor."

Where pstack is handy is that we don't need to write our own C code to examine the stack when it enters native code. We can take the Java thread's ID (0x3d46) and call pstack on it so:

[phenry@localhost My_AsmLocks]$ printf "%d\n" 0x3d46
15686
[phenry@localhost My_AsmLocks]$ pstack 15686
Thread 1 (process 15686):
#0  0x00ec0424 in __kernel_vsyscall ()
#1  0x467da6db in read () from /lib/libc.so.6
#2  0x4682cbeb in _IO_old_file_underflow () from /lib/libc.so.6
#3  0x4677ed99 in _IO_default_uflow_internal () from /lib/libc.so.6
#4  0x4677ebaf in __uflow () from /lib/libc.so.6
#5  0x46779294 in getchar () from /lib/libc.so.6
#6  0x00a8f58f in myhandler () from /mnt/hgfs/Shared/Code/JNI/MyJni/Debug/libMyJni.so
#7  0x00a8f627 in Java_com_henryp_jni_MyJni_munge () from /mnt/hgfs/Shared/Code/JNI/MyJni/Debug/libMyJni.so
#8  0xb570a84d in ?? ()
#9  0xb570345a in ?? ()
#10 0xb57003d9 in ?? ()
#11 0x0038dd65 in JavaCalls::call_helper(JavaValue*, methodHandle*, JavaCallArguments*, Thread*) () from /usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so
#12 0x004b27d9 in os::os_exception_wrapper(void (*)(JavaValue*, methodHandle*, JavaCallArguments*, Thread*), JavaValue*, methodHandle*, JavaCallArguments*, Thread*) () from /usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so
#13 0x0038cb7f in JavaCalls::call(JavaValue*, methodHandle, JavaCallArguments*, Thread*) () from /usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so
#14 0x003a062a in jni_invoke_static(JNIEnv_*, JavaValue*, _jobject*, JNICallType, _jmethodID*, JNI_ArgumentPusher*, Thread*) () from /usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so
#15 0x003aae9b in jni_CallStaticVoidMethod () from /usr/java/jdk1.7.0_07/jre/lib/i386/client/libjvm.so
#16 0x00bc9384 in JavaMain () from /usr/java/jdk1.7.0_07/bin/../jre/lib/i386/jli/libjli.so
#17 0x468a4a2e in start_thread () from /lib/libpthread.so.0
#18 0x467ea81e in clone () from /lib/libc.so.6

giving us much the same result.

Addendum

When using jstack, you might have noticed the last line looks something like:

JNI global references: 114

This refers to how many global references still exist that were created in the JNI code [1]. By global I don't mean that were created with methods like this:

    for (i = 0 ; i < 10 ; i++) {
        ret = (*env)->NewStringUTF(env, msg);
    }

This makes no difference to the count. But, replace the line with this [2]:

        jclass cls1 = (*env)->GetObjectClass(env, obj);
        cls = (*env)->NewGlobalRef(env, cls1);

and you quickly see the count rise:

$ watch "jstack `jps | grep MyJni | perl -pe s/\ .*//g` | grep JNI"

This check may be why JNI has a reputation for being slow (but that's perhaps only compared to the optimised code that JIT creates).

[1] Oracle JNI Spec.



JNI, C++ and Name Mangling


The Problem

JNI has been around for a long time but there isn't a huge amount of information out there when things go wrong. You might see a horrible exception like:


[phenry@localhost MyTest]$ java -Djava.library.path=/mnt/hgfs/Shared/Code/JNI/MyJni/Debug -cp target/classes/ com.henryp.jni.MyJni
Exception in thread "main" java.lang.UnsatisfiedLinkError: com.henryp.jni.MyJni.munge(Ljava/lang/String;)Ljava/lang/String;
at com.henryp.jni.MyJni.munge(Native Method)
at com.henryp.jni.MyJni.main(MyJni.java:22)

which doesn't tell you an awful lot about what went wrong. To make matters worse, the problem can be with your C/C++ rather than your Java - making things much harder to debug.

The Code

The Java code is very simple.

package com.henryp.jni;

public class MyJni {
    
    static {
        System.loadLibrary("MyJni");
    }
    
    private native String munge(String string);

    public static void main(String[] args) {
        MyJni app = new MyJni();
        System.out.println(app.munge("test message"));
    }
}

Note: on Linux, the actual file name defined in loadLibrary is prepended with lib and appended with .so, so in this example, the JVM is looking for something called libMyJni.so

Executing:

javah -classpath target/classes -d target com.henryp.jni.MyJni

produces a file com_henryp_jni_MyJni.h that looks like:

/* DO NOT EDIT THIS FILE - it is machine generated */
#include
/* Header for class com_henryp_jni_MyJni */

#ifndef _Included_com_henryp_jni_MyJni
#define _Included_com_henryp_jni_MyJni
#ifdef __cplusplus
extern "C" {
#endif
/*
 * Class:     com_henryp_jni_MyJni
 * Method:    munge
 * Signature: (Ljava/lang/String;)Ljava/lang/String;
 */
JNIEXPORT jstring JNICALL Java_com_henryp_jni_MyJni_munge
  (JNIEnv *, jobject, jstring);

#ifdef __cplusplus
}
#endif
#endif

Writing some C++ code that does nothing but print out what it was given and return a new string seemed straightforward:

#include <iostream>
#include "com_henryp_jni_MyJni.h"
using namespace std;

JNIEXPORT jstring JNICALL Java_com_henryp_jni_MyJni_munge
  (JNIEnv * env, jobject obj, jstring str) {
        printf("Java_com_henryp_jni_MyJni_munge called!\n");
        char* msg = "this is a test";
        return (*env)->NewStringUTF(env, msg);
}

and compiling it was a breeze:

g++ -I/usr/java/latest/include/linux -I/usr/java/latest/include/ -shared src/MyJni.cpp -o Debug/libMyJni.so

(Note the -shared. This is telling it to not produce an executable but to "produce a shared object which can then be linked with other objects to form an executable." [1])

The Solution

So, why did I get the Error at the top of this post? Well, the JVM loads the library without error (it will barf on loadLibrary if there is something wrong with the shared object). So, the problem is with the method. I never see it print out this is a test so it never gets that far. It must be with the method definition itself.

[phenry@localhost MyJni]$ nm Debug/libMyJni.so | grep munge
0000060d t _GLOBAL__sub_I__Z31Java_com_henryp_jni_MyJni_mungePPK19JNINativeInterface_P8_jobjectS4_
00000598 T _Z31Java_com_henryp_jni_MyJni_mungePPK19JNINativeInterface_P8_jobjectS4_

Hmm, the method Java_com_henryp_jni_MyJni_munge doesn't actually exist in my shared object. This is due to C++ using name mangling to allow multiple usage of a method name in different namespaces.

Writing my shared object in C and compiling with:

gcc -I/usr/java/latest/include/linux -I/usr/java/latest/include/ -shared src/MyJni.c -o Debug/libMyJni.so

solved the problem. Now, I can see my method.

[phenry@localhost MyJni]$ nm Debug/libMyJni.so | grep munge
00000468 T Java_com_henryp_jni_MyJni_munge

This answer on Stackoverflow shows how to write your code in C++ and link it to a C implementation of the autogenerated JNI header file. The author doesn't say why he prefers to compile JNI in C but this could be why.

Monday, March 17, 2014

Mind Reading a JVM on Linux


I'm currently looking at what appears to be a memory leak in a Java process that uses native Tibco libraries.

To help me see what's going on, I discovered I could read the process's memory in Linux. I could do this on a machine running the 3.6.10 kernel but had trouble on the 2.6.16 kernel.

It appears that the memory of a process is available at:

/proc/PID/mem

So, running this program:

package com.phenry.memory;

import java.io.File;
import java.io.FileNotFoundException;
import java.io.IOException;
import java.io.RandomAccessFile;

public class AnalyserMain {

    public static void main(String[] args) {
        try {
            read(args);
        } catch (IOException e) {
            e.printStackTrace();
        }
    }

    private static void read(String[] args)
        throws FileNotFoundException,
        IOException {
        String              filename            = "/proc/" + args[0] + "/mem";
        RandomAccessFile    randomAccessFile    = new RandomAccessFile(new File(filename), "r");
        byte[]              b                   = new byte[1024 * 64];
        long                offset              = Long.parseLong(args[1], 16);
        randomAccessFile.seek(offset);
        int                 off                 = 0;
        
        randomAccessFile.read(b, off, b.length);
        System.out.println("output = " + new String(b));
    }

}

with the PID of my Java process (2801 in this case) as an argument and an address taken from pmap, so:

[henryp@corsair MyMemAnalyser]$ pmap 2801 | grep anon | head
000000000095a000    132K rw---    [ anon ]
00000006f0000000 120832K rw---    [ anon ]
00000006f7600000  28160K -----    [ anon ]
.
.

I could see this:

[henryp@corsair MyMemAnalyser]$ java -classpath bin com.phenry.memory.AnalyserMain 2801 000000000095a000 | strings 
output = 
/usr/java/jdk1.7.0_51/bin/java
org.eclipse.equinox.launcher.Main
/usr/java/jdk1.7.0_51/jre/lib/amd64/server/libjvm.so
/usr/java/jdk1.7.0_51/jre/lib/amd64/server
libjvm.so
/lib64/libm.so.6
/lib64
libm.so.6
/usr/java/jdk1.7.0_51/jre/lib/amd64/server/libjvm.so
libm.so.6
u"V9
t"V9
DCmdFactory
SharedDecoderLock
-Djava.class.path=.
.
.

I've not found the cause of the memory leak yet but this takes me closer.

Memory leaks in a native library?


Everybody should be proficient with examining Java heaps. However, if your Java process uses native libraries (Tibco in our case), diagnosing memory leaks becomes harder.

These are a few notes I've made when trying to ascertain what is going on when our 4g Java heap looks fine but our off-heap usage (as shown by the pmap Linux command) has now approached 12g!

Say we wanted to know what our process was linked to. We can do this with:

[phenry@localhost MemLeaker]$ ldd leaker 
linux-gate.so.1 =>  (0x00bf0000)
libstdc++.so.6 => /usr/lib/libstdc++.so.6 (0x47007000)
libm.so.6 => /lib/libm.so.6 (0x46903000)
libgcc_s.so.1 => /lib/libgcc_s.so.1 (0x468cc000)
libc.so.6 => /lib/libc.so.6 (0x46710000)
/lib/ld-linux.so.2 (0x466ee000)

where leaker is an executable I created in C++.

Say, my program creates a thread using pthread_create. Where does this thread live? Well, going through those above files that my executable links, I found the one by doing this:

[phenry@localhost MemLeaker]$ nm -D /usr/lib/libstdc++.so.6 | grep thread | grep create
         w pthread_create
         w pthread_key_create

The nm command lists the symbols from the object files.

Now, say I was to dump the memory of a process (it need not be a JVM but let's say this one is) I would do this:


[henryp@corsair DumpMemory]$ gdb -p YOUR_PID_HERE
.
.
(gdb) gcore /hdda1/java.core

(The gdb is the GNU debugger. Think of it as attaching a Java debugger to a JVM).

Note: this file is big. It was 17g for a small Java program so make sure you have disk space.

Now examine it with:

[henryp@corsair DumpMemory]$ gdb --core=/hdd1/java.core /usr/java/jdk1.7.0_51//bin/java
.
.
(gdb) bt
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:218
#1  0x00007f4656e4d2f8 in os::PlatformEvent::park(long) () from /usr/java/jdk1.7.0_51/jre/lib/amd64/server/libjvm.so
#2  0x00007f4656e4e044 in os::sleep(Thread*, long, bool) () from /usr/java/jdk1.7.0_51/jre/lib/amd64/server/libjvm.so
#3  0x00007f4656cb6612 in JVM_Sleep () from /usr/java/jdk1.7.0_51/jre/lib/amd64/server/libjvm.so
#4  0x00007f464d012cd8 in ?? ()
#5  0x00007f46566377d0 in ?? ()
#6  0x00007f4656637820 in ?? ()
#7  0x00007f46566377c0 in ?? ()
#8  0x0000000000000000 in ?? ()

Picking a thread at random, we see it's in JVM_Sleep in the libjvm shared object. Let's just check:

[henryp@corsair DumpMemory]$ objdump -t /usr/java/jdk1.7.0_51/jre/lib/amd64/server/libjvm.so | grep JVM_Sleep
000000000067d2d0 g     F .text 000000000000045c              JVM_Sleep

"The text section of a program is where the program instructions live." [1]

If you want to look for text at these addresses, you need something like this:

(gdb) x/1000c 0x00007fb22c000000
0x7fb22c000000: 32 ' ' 0 '\000' 0 '\000' 44 ',' -78 '\262' 127 '\177' 0 '\000' 0 '\000'
0x7fb22c000008: 0 '\000' 0 '\000' 0 '\000' 0 '\000' 0 '\000' 0 '\000' 0 '\000' 0 '\000'
0x7fb22c000010: 0 '\000' 16 '\020' 2 '\002' 0 '\000' 0 '\000' 0 '\000' 0 '\000' 0 '\000'
0x7fb22c000018: 0 '\000' 16 '\020' 2 '\002' 0 '\000' 0 '\000' 0 '\000' 0 '\000' 0 '\000'

The syntax is:

x/nfu a

where n is the number of u units with format f starting at address a.

You can also search the memory for a particular string with:

(gdb) find /b 0x00601000, 0x7FFF175E900, 'P', 'h', 'i', 'l', 'l'

Where the syntax can be found here.

Alternatively, you can dump the memory to a file and then run it through the strings command to make it  easier to read with:

(gdb) dump binary memory FILE_NAME START_ADDRESS END_ADDRESS

More information on core dumps can be found here.

Saturday, March 15, 2014

Setting up an environment to look at Linux source code


Just a quick note to remind myself of what to do when I look at Linux source files. In this case, I wanted the glibc source code. First, find the version you need:

[root@localhost rpmbuild]# rpm -q glibc
glibc-2.14.1-6.i686

Download the associated source file and install it. If you get warnings about the mockbuild user, run:

yum install mock
useradd -s /sbin/nologin mockbuild

What frustrated me for a while was where my files were after I ran rpm -ivh RPM_FILE

First, I ran this to see what files I was playing with:

[root@localhost Shared]# rpm -q -filesbypkg -p glibc-2.14.1-6.src.rpm
glibc                     glibc-2.14.1-fedora.tar.xz
glibc                     glibc-2.14.1.tar.xz
glibc                     glibc-fedora.patch
glibc                     glibc-ia64-lib64.patch
glibc                     glibc-ports-2.14.1-1-g3eb1dbf.tar.xz
glibc                     glibc-rh767696.patch
glibc                     glibc-rh794797.patch
glibc                     glibc.spec

But they didn't seem to have installed anywhere. Finally, I worked out that the files get put:

[root@localhost Shared]# ls -ltra ~/rpmbuild/SOURCES/
total 21972
-rw-rw-r--. 1 mockbuild mockbuild 10120512 Oct  7  2011 glibc-2.14.1.tar.xz
-rw-rw-r--. 1 mockbuild mockbuild   407660 Oct 28  2011 glibc-2.14.1-fedora.tar.xz
-rw-rw-r--. 1 mockbuild mockbuild   496968 Oct 28  2011 glibc-ports-2.14.1-1-g3eb1dbf.tar.xz
drwxr-xr-x. 4 root      root          4096 Dec 25  2011 ..
-rw-r--r--. 1 mockbuild mockbuild     8977 Feb 20  2012 glibc-rh794797.patch
-rw-r--r--. 1 mockbuild mockbuild     2789 Feb 20  2012 glibc-rh767696.patch
-rw-r--r--. 1 mockbuild mockbuild     4294 Feb 20  2012 glibc-ia64-lib64.patch
-rw-r--r--. 1 mockbuild mockbuild   143612 Feb 20  2012 glibc-fedora.patch
drwxr-xr-x. 2 root      root          4096 Mar 15 06:50 .

How frustrating. Follow this link to see how to apply the patches.

Update

Forgot to mention: if you want to step into the code using Eclipse, you'll need to add the debug information. This is how I did it for glibc:

First, get the version information:

[henryp@corsair ~]$ rpm -qa glibc
glibc-2.15-59.fc17.i686
glibc-2.15-59.fc17.x86_64

Then download and install it with:

[henryp@corsair ~]$ sudo debuginfo-install glibc-2.15-59.fc17.x86_64

Next time you debug (I'm using Eclipse IDE for C/C++ Developers, Kepler SR, Build id: 20140224-0627), you can step into glibc code!

Monday, March 10, 2014

Locks and 'Implausible' Behaviour


In a recent bug, we found some dodgy code that, although it didn't hold the lock it needed, should have worked most of the time. That is, it appeared that another thread would have had to have seized the lock and relinquished it thousands of times while the first thread just executing a simple line. This at first seemed implausible to us.

So, we did an experiment. The code below creates 2 threads that contend for a lock. Once they have the lock, they increment a counter and make a kernel call. A third thread gets the data every second and spits it out.

This managing thread executes code like this:

    private final Lock lock = new ReentrantLock();

    private void doTest() {
        Locker locker1 = new Locker(lock);
        Thread thread1 = new Thread(locker1);

        Locker locker2 = new Locker(lock);
        Thread thread2 = new Thread(locker2);

        locker1.setOther(locker2);
        locker2.setOther(locker1);

        thread1.start();
        thread2.start();

        while (true) {
            pauseForOneSecond();
            System.out.println(locker1);
            System.out.println(locker2);
            lock.lock();
            locker1.resetMax();
            locker2.resetMax();
            lock.unlock();
        }
    }

While the contending threads execute code like this:

class Locker implements Runnable {

    private final Lock lock;

    private long       count;

    private Locker     other;

    private long       lastOther;
   
    private long       maxDiff;

    private long       diff;

    private long       doNotOptimizeAway = currentTimeMillis();

    @Override
    public void run() {
        while (true) {
            increaseCount();
        }
    }

    void increaseCount() {
        lock.lock();
        count++;

        if (other.count == lastOther) {
            diff++;
        } else {
            diff = 0; // start again
        }

        maxDiff            = max(diff, maxDiff);
        // swap counts
        lastOther          = other.count;
        other.lastOther    = count;
        // reset the other because I won this time
        other.diff         = 0;
        doNotOptimizeAway ^= currentTimeMillis(); // kernel call
        lock.unlock();
    }
.
.

This code was run on a 16-core (using hyperthreading) E5620 (2.4GHz) Linux box running a 2.6.15.60-87.1-smp kernel.

Efficiency

The total of the 2 monotonically incrementing counters for Java 1.6 over five runs was:

74 609 025
73 729 561
73 284 303
77 254 600
78 838 417

whereas Java 1.7 yields

92 043 050
93 529 925
92 779 311
92 587 899
90 993 539

which indicates that Java 1.7 handles locks with greater efficiency as more work was done.

Fairness

The difference between the two threads' counters in Java 1.6 is:

2254
  80.28
 932.1
1898
 243.7

(in units of 10 000).

For Java 1.7 it was:

4459
 412.5
2486
4284
2286

which suggests Java 1.7 is less fair when arbitrating lock contention.

Bias

One of the things I tried to measure is how many times a lock can be grabbed in a row before the other contending thread seizes it back. The output looks like:

.
.
maxDiff = 6097
maxDiff = 6617
maxDiff = 5366
maxDiff = 7593
maxDiff = 10630
maxDiff = 5318
maxDiff = 7593
maxDiff = 11025
maxDiff = 31317
maxDiff = 10273
.
.

which suggests a lock can be held for thousands of consecutive calls before the other thread had a look-in.

Conclusion

Implausible as it sounds, race conditions that may look staggeringly unlikely in your code can be quite common as the JVM 'batches' lock operations to make the overall performance much more efficient.