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

Question

I read from several other reports that people usually get around 480 ns on a simple, basic JNI call:

From What makes JNI call slower?

For common methods, last year, I found calls an average of 40 ns on my Windows desktop and 11 ns on my Mac desktop.

Out of Possible Performance Improvements Using JNI?

However, JNI calls often take about 30 ns.

When I call simple methods in my JNI code (simple I mean no more than one time int argument returning an int type), I get a round-trip call time (measured using System.nanoTIme) between 50,000 - 80,000 ns.

If I do a warm-up of a virtual machine and start a call several hundred times before synchronizing it, I still get about 2000-4000 ns (below 800-1000). (As stated above, I heard others report 100 ns .. and have 10-20 times more than what happens with frequent calls.)

Is this normal speed? What could be the reason that my own code will be called so 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 for correcting the value of the gamma of pixels (I have implemented my own code since publication).

Java performance test:

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

This is the warm-up code. Most prints are read by 800-1000ns after the initial call.

Unfortunately, I may have to abandon this because it should be used for rendering, and calling it thousands of times per second will reduce the frame rate to 1 FPS.

System Information:

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

Windows 7 64-bit

RAM 16 GB

i7-3770 Quad Core @ 3.4-3.9ghz

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

Answer 1

Is this normal speed?

Not. If you really get 50,000-80,000 ns on a JNI call, something strange happens.

What could be the reason that my own code will be called so slower?

I do not know. It could be just about everything. But if you provided us with your own code and Java code, we could better explain.

My money would be on this would NOT be a problem with JNI calls in general. Rather, I expect this to be an artifact of how you compare. There are many things you can do (or not do) that will cause the Java test result to give false results. We need to see your benchmarking.

---

So, your update indicates that your previously reported timings (50,000-80,000 or 2000-4000) are incorrect or irrelevant. The terms 800-1000ns sound believable given the following.

I think there are three drawbacks in your test.

• You are trying to measure a time interval in the order of several nanoseconds. But what your measurements do not take into account is that calling System.nanoTime() takes a considerable amount of time. What you need to do is measure the time it takes to make several THOUSAND or MILLION JNI calls between each pair of System.nanoTime() calls, then calculate and print the average.

• Your code does not separate the time taken to call the JNI from the time taken to complete the call body. (Or maybe this is so ... and you have not shown us this code.). I suspect gamma correction will take significantly longer than the JNI overhead.

• Your workout is inadequate. It is doubtful that you have been using code long enough to compile JIT. In addition, the fact that your test code is limited to one method call means that even if the JIT compiler really works, chances are d never call a JIT-compiled version of the method. Put the test code in the method and call the method again.

Answer 2

Heating is too short. The method is called after ~ 10,000 calls. Also, move the loop body to the method, since there is a difference between an “in place” infinite loop and one delete.