Skip to main content

"Object.wait" and "ref.ReferenceQueue.remove"

6 replies [Last post]
erans
Offline
Joined: 2006-08-30

Hello.

I ran a program under the "hprof" tool using the following options:
cpu=times,depth=10
and I'm quite confused with the 2 topmost entries in the resulting profile:

[...]
CPU TIME (ms) BEGIN (total = 2283396) Wed Aug 30 21:46:51 2006
rank self accum count trace method
1 36.25% 36.25% 105 301658 java.lang.Object.wait
2 27.41% 63.66% 220 301668 java.lang.ref.ReferenceQueue.remove
3 2.77% 66.44% 1630472 313222 java.lang.AbstractStringBuilder.append
4 1.75% 68.18% 203809 313231 java.lang.StackTraceElement.toString
5 1.57% 69.75% 1630472 313223 java.lang.StringBuilder.append
[...]

Why is the application spending most of the time waiting?
My program certainly doesn't call neither "wait" nor "remove", so where do they come from?

Although this post:
http://forums.java.net/jive/thread.jspa?forumID=60&threadID=1636&message...
discussed a seemingly similar issue, the final solution pointed to an "event loop" problem whereas I don't use threads nor any "graphics" code.

What I also don't understand is that, when I run the profiler with these options:
cpu=samples,interval=1,depth=10
the "wait" and "remove" methods do not appear in the output!

How can I found out what is causing the problem?

Thanks and best regards,
Gilles

P.S. I'm using Linux with:
java version "1.5.0_07"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_07-b03)
Java HotSpot(TM) Client VM (build 1.5.0_07-b03, mixed mode, sharing)

Reply viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.
ahmetaa
Offline
Joined: 2003-06-21

i would suggest Yourkit Profiler. it is fantastic.

linuxhippy
Offline
Joined: 2004-01-07

the reason why the profiles differ is that Object.wait() does not consume cpu-cycles as soon as the thread is in waiting-state.

Somehow you must call wait, if you don't do it directly then maybe some code you call calls wait(). Its hard to tell if you don't post what your code does exactly. Do you do any kind of blocking (java.io) IO?

lg Clemens

erans
Offline
Joined: 2006-08-30

Hi.

I've now run "hprof" with:
cpu=samples,interval=1,thread=y,lineno=y,monitor=y

The output (excerpts):

MONITOR DUMP BEGIN
THREAD 200001, trace 300000, status: ZO
THREAD 200002, trace 300000, status: ZO
THREAD 200003, trace 300000, status: R
THREAD 200004, trace 300001, status: R
THREAD 200005, trace 300103, status: CW
THREAD 200006, trace 300105, status: CW
THREAD 200007, trace 300595, status: R
MONITOR DUMP END
CPU SAMPLES BEGIN (total = 1460) Thu Aug 31 18:53:18 2006
rank self accum count trace method
1 19.66% 19.66% 287 300262 java.lang.Throwable.getStackTraceElement
2 6.92% 26.58% 101 300342 sun.misc.FloatingDecimal.dtoa
3 5.82% 32.40% 85 300271 java.io.FileOutputStream.writeBytes
4 2.81% 35.21% 41 300332 java.lang.Throwable.fillInStackTrace
5 1.99% 37.19% 29 300381 java.lang.AbstractStringBuilder.append
6 1.30% 38.49% 19 300301 java.lang.StringBuilder.toString
7 1.30% 39.79% 19 300317 java.lang.AbstractStringBuilder.expandCapacity
8 1.30% 41.10% 19 300414 java.lang.StringBuilder.toString
9 1.23% 42.33% 18 300114 java.lang.ClassLoader.defineClass1
10 1.23% 43.56% 18 300284 java.lang.String.
11 1.10% 44.66% 16 300324 java.lang.StringBuffer.toString
12 1.03% 45.68% 15 300320 sun.misc.FloatingDecimal.dtoa
13 0.96% 46.64% 14 300475 gaia.gwp43060.tools.numeric.rootfinding.Brent.findRoot

The method in the last position (13) is the only one which is explicitely part of my code.

Here is the relevant trace for the method in position 1:

TRACE 300262: (thread=200001)
java.lang.Throwable.getStackTraceElement(Throwable.java:Unknown line)
java.lang.Throwable.getOurStackTrace(Throwable.java:592)
java.lang.Throwable.printStackTrace(Throwable.java:511)
org.apache.log4j.spi.LocationInfo.(LocationInfo.java:105)

So, does that mean that the logging management (Log4j) uses 20 times more CPU than the "useful" part of the program?

Also, about the profile in my previous post, for which you mentioned that "wait" doesn't consume any CPU, I find the doc for hprof quite misleading:

HPROF can collect CPU usage information by injecting code into every method entry and exit, keeping track of exact method call counts and the time spent in each method.

I'd think that spending time in a method implies that the CPU cannot execute the code that's in another method. Hence the output makes it fairly unobvious that "wait" doesn't consume any time...

The answer to your question on blocking IO is "no"; at least not in the "user" code: It is a simulation, which receives input parameters from a "properties" file and then runs to completion, outputting the result (a a few dozen numbers) to an ascii file.
But then maybe log4j does some things that make it utterly unsuitable (?) in this kind of code.

Many thanks for trying to help.
Gilles

linuxhippy
Offline
Joined: 2004-01-07

> So, does that mean that the logging management
> (Log4j) uses 20 times more CPU than the "useful" part
> of the program?
It seems so - however I would recommend not to trust hprof too much, better use Netbean's profiler which is far better.
By the way it seems like exceptions are thrown which never good for performance ;-)

> I'd think that spending time in a method implies that
> the CPU cannot execute the code that's in another
> method. Hence the output makes it fairly unobvious
> that "wait" doesn't consume any time...
No the output is correct, since your program does not consume CPU cycles. You can choose wether you would like to see samples or time.

> The answer to your question on blocking IO is "no";
> at least not in the "user" code: It is a simulation,
> which receives input parameters from a "properties"
> file and then runs to completion, outputting the
> result (a a few dozen numbers) to an ascii file.
> But then maybe log4j does some things that make it
> utterly unsuitable (?) in this kind of code.
Yes but then its blocking IO - you use FileIO twice to read the properties file and to write your ascii file.
I guess Object.wait() comes from the java.io code waiting for some NIO events to happen (like more data available).

Log4J is super, if it does not work great for you - you do most likely something wrong.If you log like a mad cow or have exceptions during prcessing - well then don't wonder.
Furthermore Log4J also does FileIO, so another reason why wait() could be called.

lg Clemens

erans
Offline
Joined: 2006-08-30

Here is the output from "hprof", using an empty configuration file for Log4j:

CPU SAMPLES BEGIN (total = 212) Fri Sep 1 15:16:21 2006
rank self accum count trace method
1 8.96% 8.96% 19 300114 java.lang.ClassLoader.defineClass1
2 4.72% 13.68% 10 300122 java.util.zip.ZipFile.open
3 4.72% 18.40% 10 300194 sun.nio.cs.UTF_8$Decoder.decodeArrayLoop
4 2.83% 21.23% 6 300257 gaia.gwp43060.tools.numeric.rootfinding.Brent.findRoot
5 1.89% 23.11% 4 300134 java.util.zip.Inflater.inflateBytes
6 1.89% 25.00% 4 300288 gaia.gwp43060.tools.numeric.rootfinding.Brent.findRoot
7 1.42% 26.42% 3 300299 gaia.gwp43060.tools.numeric.rootfinding.Brent.findRoot
8 1.42% 27.83% 3 300305 gaia.gwp43060.tools.numeric.rootfinding.Brent.findRoot
9 1.42% 29.25% 3 300311 gaia.gwp43060.tools.numeric.rootfinding.Brent.findRoot
10 0.94% 30.19% 2 300126 gaia.gwp43060.binary.Component.
11 0.94% 31.13% 2 300143 java.lang.Throwable.fillInStackTrace
12 0.94% 32.08% 2 300146 java.util.zip.InflaterInputStream.
13 0.94% 33.02% 2 300192 java.util.zip.Inflater.init
14 0.94% 33.96% 2 300215 org.apache.commons.configuration.BaseConfiguration.
15 0.94% 34.91% 2 300268 gaia.gwp43060.tools.numeric.rootfinding.Brent.findRoot
16 0.94% 35.85% 2 300274 gaia.gwp43060.tools.numeric.rootfinding.Brent.findRoot
17 0.94% 36.79% 2 300295 gaia.gwp43060.tools.numeric.rootfinding.Brent.findRoot
18 0.94% 37.74% 2 300302 gaia.gwp43060.tools.numeric.rootfinding.Brent.findRoot
19 0.94% 38.68% 2 300304 gaia.gwp43060.tools.numeric.rootfinding.Brent.findRoot
20 0.94% 39.62% 2 300306 java.lang.StrictMath.log

That's seems much better.
I assume that the high rank of "java.lang.ClassLoader.defineClass1" is because the program just runs for a few seconds.

> By the way it seems like exceptions are thrown which
> never good for performance ;-)

Yes, thanks for pointing that out; I was doing something stupid :-} Now, one the the "Throwable.fillInStackTrace" disappeared from the output. There is yet another one (at position 11) which, this time, my code is not responsible for, and here is the corresponding trace:
TRACE 300143: (thread=200001)
java.lang.Throwable.fillInStackTrace(Throwable.java:Unknown line)
java.lang.Throwable.(Throwable.java:218)
java.lang.Exception.(Exception.java:59)
java.lang.ClassNotFoundException.(ClassNotFoundException.java:65)
java.net.URLClassLoader$1.run(URLClassLoader.java:200)
java.security.AccessController.doPrivileged(AccessController.java:Unknown line)
java.net.URLClassLoader.findClass(URLClassLoader.java:188)
java.lang.ClassLoader.loadClass(ClassLoader.java:306)
java.lang.ClassLoader.loadClass(ClassLoader.java:299)
sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:268)

But, again, maybe this is just normal for a short-lived program.

> Log4J is super, if it does not work great for you -
> you do most likely something wrong.If you log like a
> mad cow or have exceptions during prcessing - well
> then don't wonder.
> Furthermore Log4J also does FileIO, so another reason
> why wait() could be called.

Well, indeed, it's Log4j-related file IO which was responsible for the "Throwable.getStackTraceElement" (and "wait") since after reducing the amount of log to zero, this method also disappeared from the profile...

Thanks for your help.
Gilles

P.S. You mentioned NetBeans's profiler. As I don't use NetBeans, do you know whether the profiler can be used independently, e.g. called from an "ant" file?

linuxhippy
Offline
Joined: 2004-01-07

Hi again,

> java.lang.ClassNotFoundException.(ClassNotFound
> Exception.java:65)
This is because by design classloaders tell each other via exceptions that they can't load the requested class themself and so their parent-classloader tries again.
So exceptions are a bit mis-used for this case - however thinking about the few thousand times this normally happens no need to worry.

> P.S. You mentioned NetBeans's profiler. As I don't
> use NetBeans, do you know whether the profiler can be
> used independently, e.g. called from an "ant" file?
This is two stage - you run the JVM (6.0 recommended) with a special argument, and just attach the profiler using "global attach". So your program can be started from ant, however profiling itself is as far as I know not scriptable and has to be done with the Netbeans-Gui.

lg Clemens