Java JNI calls are slower than expected (at least 2 ms/call)

Question

I've read from several other reports that people generally get around 4-80 ns on a plain, basic JNI call:

From What makes JNI calls slow?

For trivial native methods, last year I found calls to average 40 ns on my Windows desktop, and 11 ns on my Mac desktop ..

From Possible increase of performace using JNI?

However JNI calls often take around 30 ns ..

When I call simple methods in my JNI code (by simple I mean no more than one argument of time int returning type int), I'm getting a round trip call time (measured with System.nanoTIme) of between 50,000-80,000 ns.

If I do a VM "warm-up" and run the call a few hundred times before timing it, I still get about 2000-4000 ns (800-1000 below). (As stated above, I have heard others report < 100 ns.. and having 10-20 times higher than that does add up when making frequent calls.)

Is this normal speed? What could be causing my native code to be called so much slower?

UPDATE:

JNIEXPORT jint JNICALL Java_com_snap2d_gl_RenderControl_correctGammaNative
  (JNIEnv *env, jobject obj, jint pixel) {
    return X2D_correctGamma(pixel, 1.0f);
}

Where X2D_correctGamma(int,float) is a method to correct a pixel's gamma value (I've implemented native code since posting).

Java benchmarking:

    for(int i = 0; i < 100; i++) {
        long t1 = System.nanoTime();
        correctGammaNative(0xFFF);
        long t2 = System.nanoTime();
        System.out.println(t2 - t1);
    }

That's the "warm-up" code. Most of the printlns read 800-1000ns after the initial call.

Unfortunately, I may have to scrap this, because it's supposed to be used in rendering, and calling this thousands of times per second is bringing the frame rate down to 1 FPS.

System Info:

Behaves similarly on: JDK1.6.0_32 (64-bit), JDK1.7.0_04 (64-bit), and JRE1.7.0_10 (32-bit)

Windows 7 64-bit

16GB RAM

i7-3770 quad-core CPU @ 3.4-3.9ghz

GNU GCC MinGW Compilers (32-bit and 64-bit)

Answer 1

Is this normal speed?

No. If you are really getting 50,000-80,000 ns per JNI call, something weird is going on.

What could be causing my native code to be called so much slower?

No idea. It could be almost anything. But if you showed us the native code and the Java code we'd be in a better position to explain.

My money would be on this NOT being a problem with the JNI calls at all. Rather, I expect it is an artefact of the way that you are benchmarking. There are lots of things that you can do (or fail to do) that will cause a Java benchmark to produce spurious results. We need to see your benchmarking code.

---

OK so, your update indicates that your earlier reported timings (50,000-80,000 or 2000-4000) are incorrect or irrelevant. Timings of 800-1000ns sound plausible, given the following.

I think there are three flaws in your benchmark.

• You are trying to measure a time interval in the order of a few nanoseconds. But what your measurement is not taking account of is that a call to System.nanoTime() takes a significant time. What you need to do is measure the time it takes to make a few THOUSAND or MILLION JNI calls between each pair of System.nanoTime() calls, then calculate and print the average.

• Your code doesn't separate the time taken to make the JNI call from the time taken to execute the call body. (Or maybe it does ... and you haven't shown us that code.). I suspect that the gamma correction will take significantly longer than the JNI call overhead.

• Your warmup is inadequate. It is doubtful that you are running the code for long enough for JIT compilation to kick in. Furthermore, the fact that your benchmark code is confined to a single method call means that even if the JIT compiler did run, the chances are that you'd never call the JIT-compiled version of the method. Put the benchmark code into a method and call the method repeatedly.