Skip to main content

Swing CPU-bound in sun.awt.windows.WToolkit.eventLoop

10 replies [Last post]
coxcu
Offline
Joined: 2003-06-11
Points: 0

Hi,

Every once in a while, I'll have a Swing application that is CPU bound on Windows. So, I'll profile it with -agentlib:hprof=cpu=samples or something similar.
http://java.sun.com/developer/technicalArticles/Programming/HPROF.html

Profiling produces something like this:
CPU SAMPLES BEGIN (total = 201533) Mon Oct 10 09:51:20 2005
rank self accum count trace method
1 49.19% 49.19% 99144 300516 sun.awt.windows.WToolkit.eventLoop
2 13.05% 62.25% 26303 301341 sun.java2d.loops.Blit.Blit
3 8.90% 71.15% 17936 301060 sun.awt.windows.WGlobalCursorManager.findHeavyweightUnderCursor
4 5.32% 76.47% 10723 301061 sun.java2d.loops.DrawGlyphList.DrawGlyphList
5 3.80% 80.26% 7651 301010 sun.reflect.Reflection.getClassAccessFlags
6 2.38% 82.64% 4797 301067 sun.font.FontManager.getFont2D
7 2.04% 84.69% 4120 301069 sun.awt.windows.Win32DDRenderer.doFillRectDD
8 1.93% 86.62% 3884 301335 sun.java2d.loops.FillRect.FillRect
9 1.76% 88.38% 3554 301045 sun.awt.windows.Win32BlitLoops.Blit
10 1.64% 90.02% 3299 300336 java.lang.String.intern

TRACE 300516:
sun.awt.windows.(WToolkit.java:Unknown line)
sun.awt.windows.WToolkit.run(WToolkit.java:269)
java.lang.Thread.run(Thread.java:595)

Judging by the profile, sun.awt.windows.WToolkit.eventLoop is clearly the problem. Yet, I have no idea what it is doing or why it is being invoked so much. What should my next step be? Is there some way of determining what the real problem is?

Using thread=y tells me that the AWT-Windows thread is taking all of the CPU--which I could have guessed.

TRACE 300514: (thread=200014)
sun.awt.windows.WToolkit.eventLoop(WToolkit.java:Unknown line)
sun.awt.windows.WToolkit.run(WToolkit.java:269)
java.lang.Thread.run(Thread.java:595)

THREAD START (obj=500006af, id = 200014, name="AWT-Windows", group="main")

Using -agentlib:hprof=cpu=times,thread=y gives a completely different, yet no more helpful, picture.

CPU TIME (ms) BEGIN (total = 2242112) Mon Oct 10 10:43:29 2005
rank self accum count trace method
1 11.81% 11.81% 86 301472 java.lang.Object.wait
2 11.69% 23.50% 25629 301483 java.lang.ref.ReferenceQueue.remove
3 11.35% 34.85% 1 387489 java.util.TimerThread.mainLoop
4 8.44% 43.29% 1 384658 sun.awt.windows.WToolkit.run

TRACE 301472: (thread=200004)
java.lang.Object.wait(Object.java:Unknown line)
java.lang.ref.Reference$ReferenceHandler.run(Reference.java:Unknown line)

TRACE 301483: (thread=200005)
java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:Unknown line)
java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:Unknown line)
java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:Unknown line)

TRACE 387489: (thread=200006)
java.util.TimerThread.mainLoop(Timer.java:Unknown line)
java.util.TimerThread.run(Timer.java:Unknown line)

TRACE 384658: (thread=200013)
sun.awt.windows.WToolkit.run(WToolkit.java:Unknown line)
java.lang.Thread.run(Thread.java:Unknown line)

I don't really have any idea what this is telling me either. It looks like many things are being removed from reference queues, but that doesn't point clearly anywhere. I'm interested in what the problem is, but I'm much more interested in how to find out what the problem is.

Thanks,
Curt

Reply viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.
coxcu
Offline
Joined: 2003-06-11
Points: 0

I'm looking at a similar problem now, so I decided to write up how I solved the last one. Hopefully it will either help someone else out of a similar spot or spur someone to show me a better way.

To recap, I had a Swing application that consumed 100% CPU while just sitting there. Trying to find the bottleneck with java -agentlib:hprof didn't produce anything that seemed like good data. I posted to this forum, and got some nice suggestions, but nothing worked. Since this wasn't really interfering with development, I put the problem out of my mind and hoped that it would go away.

Later, I had someone run the software on a laptop that was much slower than my development machine. While the software was still useable, the problem was much worse. I could no longer ignore the problem.

To get good data, I spent a couple of days writing a JPDA based profiler. There were a few underdocumented corners along the way, but it was remarkably easy thanks to a nice example Trace program..
http://java.sun.com/j2se/1.5.0/docs/guide/jpda/trace.html

Even though method invocations didn't seem like the right thing to measure, they were the easiest thing to measure that might be right. As it turns out, they were completely adequate.

So, now I have a profiler that will record method invocations and let me see what method stacks are called the most. It has some nifty filtering features that java -agentlib:hprof doesn't. Namely, I can easily include or exclude classes from method profiling. This comes pretty much free from JPDA, with little work on my part.

To exclude JRE classes, I use a command line switch:
-exclude java.*;javax.*;sun.*;com.*

To concentrate on a specific class I use:
-include javax.swing.plaf.basic.BasicGraphicsUtils

Similar filtering might be a worthwhile addition to the java -agentlib:hprof profiler. For my ad-hoc profiler it is actually vital, since the program runs a few thousand times more slowly, when all classes are being profiled. That's not quite as bad as it sounds, because I only needed to profile all classes once. After that was done (overnight), I was able to use the output, to concentrate on much smaller sets of classes.

After running my profiler overnight, I had some idea about what the problem was:

For entire VM
Trace 1 sun\font\FontDesignMetrics.java:getLatinCharWidth:233
sun\font\FontDesignMetrics.java:stringWidth:285
com\sun\java\swing\SwingUtilities2.java:stringWidth:292
javax\swing\SwingUtilities.java:layoutCompoundLabelImpl:931
javax\swing\SwingUtilities.java:layoutCompoundLabel:817
javax\swing\plaf\basic\BasicGraphicsUtils.java:getPreferredButtonSize:262 212329
Trace 2 java\lang\String.java:charAt:557
sun\font\FontDesignMetrics.java:stringWidth:283
com\sun\java\swing\SwingUtilities2.java:stringWidth:292
javax\swing\SwingUtilities.java:layoutCompoundLabelImpl:931
javax\swing\SwingUtilities.java:layoutCompoundLabel:817
javax\swing\plaf\basic\BasicGraphicsUtils.java:getPreferredButtonSize:262 212329
...

The next thing I wanted to know was what called BasicGraphicsUtils.java:getPreferredButtonSize() so much? This leads to a cycle: profile, examine output, change settings, profile, examine output, ... If I have to do this too often, I'm going to investigate the feasibility of keeping invocation information for every trace. No matter how deep you make the traces, you will frequently wish some of them were deeper. Conversely, if you make them really large, it can really increase the amount of noise, hide hot spots, make your profiler run more slowly, and make it run out of memory. What I really want is something like this:

For entire VM
Trace 1 sun\font\FontDesignMetrics.java:getLatinCharWidth:233
sun\font\FontDesignMetrics.java:stringWidth:285
com\sun\java\swing\SwingUtilities2.java:stringWidth:292
javax\swing\SwingUtilities.java:layoutCompoundLabelImpl:931
javax\swing\SwingUtilities.java:layoutCompoundLabel:817
javax\swing\plaf\basic\BasicGraphicsUtils.java:getPreferredButtonSize:262 212329
invoked by 45 -- 76.239%
invoked by 98 -- 22.451%
...

So much for how I found the problem. My problem, in case anybody is curious, was one of event handling. An event handler was doing processing that would ultimately cause it to be triggered again. Thus, once it had been triggered the first time, it would trigger itself again forever, via the event queue. Now that I'm faced with a similar problem, I'm going to try replacing the AWT EventQueue to see if that can quickly provide me with effective profiling information.

- Curt

kellyohair
Offline
Joined: 2004-09-03
Points: 0

Ah, I see you did try cpu=times, sorry missed that... Windows, sigh. :^(

Since I can't find out what the actual CPU time spent per thread on Windows, this is difficult and very confusing I agree. I suspect this is a little better on Solaris where we have gethrvtime() to get the CPU per thread time, but I'm sure that doesn't help you out much, unless you have access to a Solaris machine?

I must confess that doing true multi-threaded profiling isn't easy, and the tools aren't completely up to speed for Java. The best I've seen is again on Solaris, and the Sun Studio Analyzer product available at http://www.sun.com/download/products.xml?id=41e70b09 or the DTrace tool in Solaris 10, but my experience is mostly with Solaris. If anyone has any suggestions for tools on Windows, maybe they will reply. Profiling Java apps, especially highly multi-thread ones often does require multiple kinds of profile samples, and many change & re-run experiments. And every app is often different.

If you try the Netbeans Profiler plese let us know how it goes. There are definitely many Java profilers out there. Unfortunately I won't be surprised that they all give you back slightly different information, depending on how they got their information.

In the meantime I will file an bug against HPROF to investigate this WAITING thing, maybe I can create a small
testcase that is representative and add an option to not count threads in WAITING state. Maybe I can change cpu=samples to be a little smarter.

Also, expect some performance articles on this kind of topic in the future or see
https://performance.dev.java.net/nonav/home.

-kto

mthornton
Offline
Joined: 2003-06-10
Points: 0

> Ah, I see you did try cpu=times, sorry missed that...
> Windows, sigh. :^(
>
> Since I can't find out what the actual CPU time spent
> per thread on Windows,

GetThreadTimes has been in the Windows API since Windows NT 3.5! OK, so it isn't available on Windows 9x or ME, but these are obsolete.

Mark Thornton

kellyohair
Offline
Joined: 2004-09-03
Points: 0

So Windows 98 is left out, which we do support, but perhaps I can make the use of GetThreadTimes dynamic so other Windows platforms use it, I'll file an RFE on this.

Thanks. I always appreciate the Windows help. ;^)

coxcu
Offline
Joined: 2003-06-11
Points: 0

Tom,

This problem appears on a variety of Windows 2000 and Windows XP machines of various hardware configurations. While it might be Windows-specific, it doesn't appear to be hardware specific. I usually only develop and profile this application on Windows because it currently only ships on Windows.

kto,

Actually I do have access to Linux, OS X, and x86 Solaris. I'll investigate DTrace and Sun Studio Analyzer. NetBeans didn't give me much love, however.

First off, since the language changes in Tiger, NetBeans/javac and Eclipse support slightly different languages. You have to tweak some code to move back and forth between them. These cases are becoming rarer and I'm usually not sure which compiler is right. For example, I had to add the "X" at the end of the following method to satisfy NetBeans. Alternately, I can prefix the class name when I invoke the method, which some would argue I should be doing anyway.

private static String toStringX(byte[] bytes) {
try {
return new String(bytes,"UTF-8");
} catch (UnsupportedEncodingException e) {
throw new RuntimeException(e);
}
}

Eventually, I got the application to build and run under NetBeans. Unfortunately, it won't run with the NetBeans profiler. Instead, it produces a string of messages like this:

*** Profiler Engine: redefinition failed for classes:
*** with message: Redefinition failed with error 62

Then it throws an exception like this:

java.lang.IllegalAccessException: Class java.lang.reflect.Method can not access a member of class com.foo.bar with modifiers "public abstract"

This is where I gave up on the NetBeans profiler rather than introduce additional change into the application. All thing considered, it is quite respectable for a beta profiler on a beta IDE.

tackline,

I was really hoping for a method of identifying the kind of objects causing the trouble, or (better yet) where they are being created. The book "Java Performance Tuning" by Jack Shirazi has a technique for replacing java.lang.Object with a custom version that I have used as a last resort before. Perhaps, I can find a tool for garbage collection analysis that would give me a better idea.

Thanks for all of the suggestions. They are much appreciated.

- Curt

tackline
Offline
Joined: 2003-06-19
Points: 0

Just for fun I wrote a patch to java.lang.ref.Finalizer to count the number of objects of each class finalised. You should find it easy to give it a spin, I hope.

http://jroller.com/page/tackline?entry=counting_finalised_objects

tackline
Offline
Joined: 2003-06-19
Points: 0

WToolkit.eventLoop should be called very often as it contains the Windows event loop - running in a companion to AWT Event Dispatch Thread (EDT). As WToolkit is heavily involved with native code, it's no surprise that a Java profiler doesn't help much.

ReferenceQueue is used to implement finalisation. Perhaps there is a high turnover of objects which use (non-empty) finalisers. Timer, Cursor, Font, etc.

kellyohair
Offline
Joined: 2004-09-03
Points: 0

The HPROF cpu=samples is more of a wall-clock measurement of what the most popular stack traces are. When you have Java threads that are somehow not using the CPU, but managing to stay active, then it will appear as if those stack traces are consuming large amounts of CPU time when they aren't.

You could try HPROF cpu=times instead, which will make your app run slower, but it might bringout more information. Unfortunately Windows doesn't provide a per-thread CPU time used function.

If you haven't tried the Netbeans Profiler, you might want to try that.

---

As I look at the HPROF sources, in hprof_trace.c, it appears that the basic test as to whether a thread's stack trace gets a counter increment is:
((state & JVMTI_THREAD_STATE_RUNNABLE)!=0 && (state & JVMTI_THREAD_STATE_SUSPENDED)==0 && (state & JVMTI_THREAD_STATE_INTERRUPTED)==0)
Requiring the thread to be RUNNABLE, but not explicitly suspended, and not interrupted. Looks like it doesn't ignore stack traces that represent the states of "WAITING" or "BLOCKED ON MONITOR". I suppose the results could change if hprof cpu=samples tried to remove the various thread waiting states. I'd have to think about this more.

-kto

coxcu
Offline
Joined: 2003-06-11
Points: 0

Thanks for the reply.

I think you missed the part of my post where I used "-agentlib:hprof=cpu=times". If not, could you elaborate on what you're suggesting?

I'll try the NetBeans profiler next.

My fear is that I'll gain more and more information about where the CPU time is being spent, without obtaining any more information about why or how to fix it.

This is a place where the Java platform's support for multi-threaded applications could use some work. Finding a hot spot in one thread may give little or no information about the real cause in another thread.

Stack traces have a similar problem.

tmarble
Offline
Joined: 2003-08-22
Points: 0

Curt:

What platform are you running on (i.e. Which version of Windows, which version of DirectX, which version of the JVM, which hardware : #cpus and speed, amount of RAM, video card, VRAM)?

I'll see if I can find what symptoms lead to those specific methods getting hot...

In the meantime, are you aware of documentation on Swing and Threads?
Search for Threads here...
http://java.sun.com/products/jfc/tsc/articles/index.html

This book is entirely online:
Java Platform Performance: Strategies and Tactics
http://java.sun.com/docs/books/performance/1st_edition/html/JPSwingThrea...

Also, I'm sure you are familiar with the Desktop Community:
http://community.java.net/javadesktop/

Regards,

--Tom