very slow jni code callbacks

very slow jni code callbacks

[Herman ten Brugge]

[-- Attachment #1: Type: text/plain, Size: 844 bytes --]

I have a problem with jni code callbacks.
I have attached some code that shows the problem.
The result of this code is:

# results on fedora 11
#  gcc/gcj 4.4.1
#  kernel 2.6.30.5-43.fc11.x86_64
#  openjdk fedora-29.b16.fc11-x86_64
#
#                       open jdk        gcj
# no_jni                 1.48               7.46        (  5 times slower)
# jni                   66.70           17140.00        (257 times slower)

So when not using jni in this case gcj is 5 times slower.
I suspect the jit compiler does a good for this small sample.

The code with jni calls is however 257 timer slower. I really
did not expect that. I also tried other java vm and they all
have much better performance. So I expect a problem in the
gcj library.

When I use oprofile I see at lot of calls to execute_cfa_program
and _Unwind_IteratePhdrCallback.

[-- Attachment #2: tst.tar --]
[-- Type: application/x-tar, Size: 20480 bytes --]

Re: very slow jni code callbacks

[Andrew Haley]

Herman ten Brugge wrote:
> I have a problem with jni code callbacks.
> I have attached some code that shows the problem.
> The result of this code is:
> 
> # results on fedora 11
> #  gcc/gcj 4.4.1
> #  kernel 2.6.30.5-43.fc11.x86_64
> #  openjdk fedora-29.b16.fc11-x86_64
> #
> #                       open jdk        gcj
> # no_jni                 1.48               7.46        (  5 times slower)
> # jni                   66.70           17140.00        (257 times slower)
> 
> So when not using jni in this case gcj is 5 times slower.
> I suspect the jit compiler does a good for this small sample.
> 
> The code with jni calls is however 257 timer slower. I really
> did not expect that. I also tried other java vm and they all
> have much better performance. So I expect a problem in the
> gcj library.
> 
> When I use oprofile I see at lot of calls to execute_cfa_program
> and _Unwind_IteratePhdrCallback.

I think this is a bug.  I've had a look at the code, and it's in
jni.cc: _Jv_JNI_CallAnyVoidMethodV

This calls _Jv_GetTypesFromSignature, which in turn iterates though
all the class loaders looking up the types of all the arguments.
But as far as I can see this is a pointless waste of time: the only
use of the type of each argument is to determine whether it's a
primitive type or not, and we could certainly have done that when
we created the jmethodID.  There is a field in the method struct called
ffi_arg_types, but I think it isn't used when calling C to Java via JNI.

Note that JNI calls to Java code will always be somewhat slower than
CNI since it goes though a libffi call, but this seems to me to be
crazy extreme.

I'm Cc:ing this to Tom Tromey, who wrote this code originally.

Andrew.

Re: very slow jni code callbacks

[Bryce McKinlay]

On Mon, Sep 28, 2009 at 1:03 PM, Andrew Haley <aph@redhat.com> wrote:

>> When I use oprofile I see at lot of calls to execute_cfa_program
>> and _Unwind_IteratePhdrCallback.
>
> I think this is a bug.  I've had a look at the code, and it's in
> jni.cc: _Jv_JNI_CallAnyVoidMethodV
>
> This calls _Jv_GetTypesFromSignature, which in turn iterates though
> all the class loaders looking up the types of all the arguments.
> But as far as I can see this is a pointless waste of time: the only
> use of the type of each argument is to determine whether it's a
> primitive type or not, and we could certainly have done that when
> we created the jmethodID.  There is a field in the method struct called
> ffi_arg_types, but I think it isn't used when calling C to Java via JNI.

I think the underlying issue is that jMethodID is typedef'ed to
libgcj's internal _Jv_Method. It really needs to use something more
like the interpreter's _Jv_ResolvedMethod or _Jv_JNIMethod so that the
arg types and return type (and, in fact, the ffi_cif itself) can be
resolved once and reused.

Bryce

Re: very slow jni code callbacks

[Andrew Haley]

Bryce McKinlay wrote:
> On Mon, Sep 28, 2009 at 1:03 PM, Andrew Haley <aph@redhat.com> wrote:
> 
>>> When I use oprofile I see at lot of calls to execute_cfa_program
>>> and _Unwind_IteratePhdrCallback.
>> I think this is a bug.  I've had a look at the code, and it's in
>> jni.cc: _Jv_JNI_CallAnyVoidMethodV
>>
>> This calls _Jv_GetTypesFromSignature, which in turn iterates though
>> all the class loaders looking up the types of all the arguments.
>> But as far as I can see this is a pointless waste of time: the only
>> use of the type of each argument is to determine whether it's a
>> primitive type or not, and we could certainly have done that when
>> we created the jmethodID.  There is a field in the method struct called
>> ffi_arg_types, but I think it isn't used when calling C to Java via JNI.
> 
> I think the underlying issue is that jMethodID is typedef'ed to
> libgcj's internal _Jv_Method. It really needs to use something more
> like the interpreter's _Jv_ResolvedMethod or _Jv_JNIMethod so that the
> arg types and return type (and, in fact, the ffi_cif itself) can be
> resolved once and reused.

Well, sure, but it seems to me like this is obvious and almost trivial,
so I don't understand what the problem is.  I'm guessing that it's simply
that no-one ever got around to doing it.

Andrew.

Re: very slow jni code callbacks

[Tom Tromey]

Bryce> I think the underlying issue is that jMethodID is typedef'ed to
Bryce> libgcj's internal _Jv_Method. It really needs to use something more
Bryce> like the interpreter's _Jv_ResolvedMethod or _Jv_JNIMethod so that the
Bryce> arg types and return type (and, in fact, the ffi_cif itself) can be
Bryce> resolved once and reused.

I think there is some reason we use _Jv_Method, and not something else,
for the jMethodID typedef.  I don't remember what it was.

Tom

Re: very slow jni code callbacks

[Tom Tromey]

Andrew> This calls _Jv_GetTypesFromSignature, which in turn iterates though
Andrew> all the class loaders looking up the types of all the arguments.
Andrew> But as far as I can see this is a pointless waste of time: the only
Andrew> use of the type of each argument is to determine whether it's a
Andrew> primitive type or not, and we could certainly have done that when
Andrew> we created the jmethodID.

Yeah, this could use some improvement.
Even a variant of _Jv_GetTypesFromSignature that did less work would
help.

Tom

Re: very slow jni code callbacks

[Herman ten Brugge]

On 09/28/09 21:01, Tom Tromey wrote:
> Andrew>  This calls _Jv_GetTypesFromSignature, which in turn iterates though
> Andrew>  all the class loaders looking up the types of all the arguments.
> Andrew>  But as far as I can see this is a pointless waste of time: the only
> Andrew>  use of the type of each argument is to determine whether it's a
> Andrew>  primitive type or not, and we could certainly have done that when
> Andrew>  we created the jmethodID.
>
> Yeah, this could use some improvement.
> Even a variant of _Jv_GetTypesFromSignature that did less work would
> help
I did try some older gcc releases because I once had good
results for callbacks.
The 4.1.2 release shows some different results.

#                       open jdk        gcj
# no_jni                 1.48              12.12        (  8 times slower)
# jni                   66.70             200.93        (  3 times slower)

So there must be a change some time ago that made this
much slower.

     Herman.

Re: very slow jni code callbacks

[Andrew Haley]

Herman ten Brugge wrote:

> I did try some older gcc releases because I once had good
> results for callbacks.
> The 4.1.2 release shows some different results.
> 
> #                       open jdk        gcj
> # no_jni                 1.48              12.12        (  8 times slower)
> # jni                   66.70             200.93        (  3 times slower)
> 
> So there must be a change some time ago that made this
> much slower.

It depends only on the number of active ClassLoaders, and how much
processing they do.  The fix for this is to remove the classname
lookups at runtime.

Andrew.