Why java.lang.Object.getClass() (and reflection) is slower than usual?

Question

We are encountering some strange JVM performance issues.

We have a large and somewhat opaque GUI component (Actuate Formula 1 spreadsheet).

If we initialize all of it from the Event Dispatch Thread (as you should), we find that the code runs considerably more slowly (dragging the mouse to select cells, there's a noticeable lag).

If we initialize it the first time in the main launcher thread, and only then start using it in the EDT, it runs much more quickly.

When I look at why it is performing slowly using a profiler, the method calls that are taking all of the time are:

• java.lang.Object.getClass()
• java.lang.reflect.Array.newInstance(Class, int)
• java.lang.Class.getComponentType()
• java.lang.Thread.currentThread()

We are using the 64-bit Sun Hotspot JVM on Windows 7 (the one that comes with the JDK).

Does anyone know of any reason why the above methods might perform drastically slower that usual?

I am thinking that maybe it has something to do with the order in which the classes are loaded.... is that a reasonable theory? Does anyone know of any other ways in which I can diagnose why these method calls might be taking a long time?

I've attached two screenshots from the profiler. In both, all I did was drag the mouse around the spreadsheet cells while the profiler was running. So it's just updating the GUI component and not doing very much else.

The first one is spending a lot of time in a method called "releaseLock()". For some reason, this is taking a long time because "getComponentType()" is taking a much longer time than usual.

The second one is after I did a "hack" to remove the cost of "releaseLock()" - but now it just spends lots of time in "getLock()" due to getClass() and currentThread() taking much longer than normal:

But the important thing is that if I simply change the order in which the code is initialized, none of this code takes very long to execute (it doesn't even show up in the profiler at all).

If I was to optimize getLock() the application still performs much more slowly. The problem really seems to be that methods such as getClass() are taking too long. There's no way to compensate for this - getClass() gets called in too many places!

The performance difference is noticeable even without the profiler running.

Please also remember that we cannot change any of this code - it's an external component. The challenge is to explain why the code executes so much more slowly in some circumstances vs others.

Elegit

Can you post a screenshot of profiling? Also, profiling can have a significant impact on runtime. Can you exclude those methods from profiling and see if there are other reasons for your lag? – Squawk

I don't know how to exclude these methods from the profiling but as you can see it's using sampling, and showing the breakdown. I think what the profiler is showing is valid - it's not that it's different code that is executing, it's simply that, for some reason, these method calls which are ordinarily quite inexpensive (Object.getClass()) are now taking a long time. – Elegit

Is this result consistent? Because if it only happens once, then it can easily be a sampling problem ("bad luck" in choosing when a sample is taken). – Gilcrest

It's consistent - always happens the same way. – Elegit

What are you doing in getLock() and releaseLock()? Also, when you run Thread.currentThread().getContextClassLoader() on your 'main' thread, and on the 'eventdispatcher' thread, are they the same ClassLoader implementation? Is the CL for the EDT conspicuous for its being on a potentially slow IO path to load classes (eg. inside a Jar, instead of on a filesystem?!) – Raptorial

David, interesting idea... it's the same ClassLoader instance though for both threads: sun.misc.Launcher$AppClassLoader@35a16869. I wonder though whether something else that's happening in the event dispatch thread is "ruining" things. – Elegit

getLock and releaseLock are used inside the component in what seems to me to be some severely misguided multi-threading logic. Every method is surrounded with "getLock()" and "releaseLock()". They create a separate thread which can evaluate formulas, and use this to support the scenario of the calculation thread running at the same time as the EDT. I would rather that they had not used any threading whatsoever. I think it's a red-herring though: the code is not pretty - but it's only proving to be "slow" when Object.getClass() is slow. Object.getClass() shouldn't take any time at all. – Elegit

To elaborate: even if I get rid of the calls to getLock and releaseLock with some imaginative hackery, the whole GUI component runs very slowly in many other ways. The profiler always traces it down these calls to Object.getClass() etc. – Elegit

I think you need to increase your sampling frequency to get a better picture here - the way I interpret these screen shots, there was a single sample during the execution of each of these methods (Object.getClass, etc) and the time reported in each method is an estimate based on the ratio of samples in method to total samples. But 144 samples over 13 seconds is far too few to get a good picture of your performance bottlenecks. – Sapro

Hi Alex, I understand but for a variety of reasons I trust what the profiler is telling me. Mainly, the fact that these calls are taking much longer explains why so much disparate code is all executing so slowly. The call counts is the same in the "fast" case and the "slow" case -> it's not executing more code, just the code that it is executing is executing much more slowly. In short: I don't think it's mis-measurement by the profiler. – Elegit

Your classpath contents--are any of them on remote disks (e.g. mounted via CIFS/SMB)? I wonder if the EDT is being paused during network activity when the classes were initially loaded in the EDT. A simple test could be to copy your classpath to a local disk to see if it changes the perceived responsiveness. – Liponis

Answer 1

You could try to take several mixed (java+native) jstack -m thread dumps of the application under the load.

This would probably give some hints on what is happening under the hood of Object.getClass().

See also If profiler is not the answer, what other choices do we have?.

Also take a look at What does thread dump looks like when JVM spent time in GC. Cause usual JVM thread dumps may not always be perfectly accurate as they happen only on safepoints.

Pippa