Re: sun.awt.X11.XEvent is creating 600 MB of char[] for no good reason

[Artem Ananiev]

On 10/21/2011 4:00 PM, Anthony Petrov wrote:
Hi Federico,
Indeed, this is a nasty issue. Thanks for spotting it. You may notice
that in most other places where something is logged, the code usually
checks whether logging is enabled for a certain level of logging, e.g.:

if (shapeLog.isLoggable(PlatformLogger.FINER)) {
shapeLog.finer(
"*** INFO: Setting shape: PEER: " + this
+ "; WINDOW: " + getWindow()
+ "; TARGET: " + target
+ "; SHAPE: " + shape);
}

So basically, we could simply wrap the line in question into a similar
if(){} statement to make sure it gets executed only when the FINEST
level of logging is enabled. A similar solution may also apply to
another call to enableLog.finer() in the same method just a few lines
below.

Although the fix has been already pushed to the workspace, let me wonder 
if, in addition to wrapping the logging calls with the "if ()" checks, 
we should have also rewritten isEventDisabled() to use StringBuilder?

Thanks,

Artem

Could you make a patch, test it, and post it to this mailing list for
review please?

--
best regards,
Anthony

On 10/21/2011 7:10 AM, Federico Tello Gentile wrote:
Hi.
I'm running

java -version
java version "1.7.0_147-icedtea"
OpenJDK Runtime Environment (IcedTea7 2.0pre) (7~b147-2.0~pre6-1ubuntu1)
OpenJDK 64-Bit Server VM (build 21.0-b17, mixed mode)

and profiling a simple Swing application.

Just by opening a JFrame and moving the mouse over it for 10 secods I
see 600 MB of char[] being created. I can easily create several
terabytes or those if I move the mouse a little longer. Thanks to the
incredibly efficient garbage collector the application performance is
not visibly affected on my 4GB quad core machine.

The problem is an incredibly inefficient method
sun.awt.X11.XEvent.getFieldsAsString() which I pasted at the end of this
message.

The way it it handling string concatenation forces StringBuilder to grow
many times and ends up calling Arrays.copyOf a lot of times.
It is being called by the sun.awt.X11.XWrapperBase.toString() just for
the sake of logging here:

sun.awt.X11.XComponentPeer

protected boolean isEventDisabled(XEvent e)

enableLog.finest("Component is {1}, checking for disabled event {0}", e,
(isEnabled()?"enabled":"disable"));

The worse part is that even if logging is disabled and nothing at all is
ever logged, the toString is called anyway and all those char[] are
created anyway.

Here's a NetBeans profiler memory snapshot.

http://ubuntuone.com/4xkprEzadUM4sUSdAnWlN5


This does not happen *at all* if I run the same profiling with this
openjdk version

java -version
java version "1.6.0_23"
OpenJDK Runtime Environment (IcedTea6 1.11pre) (6b23~pre10-0ubuntu5)
OpenJDK 64-Bit Server VM (build 20.0-b11, mixed mode)

I hope we can do something to improve this situation. I guess all Swing
applications are affected.

I look forward for any comments.

Here's the "thing"...

---------------------------------------------------

String getFieldsAsString() {
String ret="";

ret += ""+"type = " + XlibWrapper.eventToString[get_type()] +", ";
ret += ""+"xany = " + get_xany() +", ";
ret += ""+"xkey = " + get_xkey() +", ";
ret += ""+"xbutton = " + get_xbutton() +", ";
ret += ""+"xmotion = " + get_xmotion() +", ";
ret += ""+"xcrossing = " + get_xcrossing() +", ";
ret += ""+"xfocus = " + get_xfocus() +", ";
ret += ""+"xexpose = " + get_xexpose() +", ";
ret += ""+"xgraphicsexpose = " + get_xgraphicsexpose() +", ";
ret += ""+"xnoexpose = " + get_xnoexpose() +", ";
ret += ""+"xvisibility = " + get_xvisibility() +", ";
ret += ""+"xcreatewindow = " + get_xcreatewindow() +", ";
ret += ""+"xdestroywindow = " + get_xdestroywindow() +", ";
ret += ""+"xunmap = " + get_xunmap() +", ";
ret += ""+"xmap = " + get_xmap() +", ";
ret += ""+"xmaprequest = " + get_xmaprequest() +", ";
ret += ""+"xreparent = " + get_xreparent() +", ";
ret += ""+"xconfigure = " + get_xconfigure() +", ";
ret += ""+"xgravity = " + get_xgravity() +", ";
ret += ""+"xresizerequest = " + get_xresizerequest() +", ";
ret += ""+"xconfigurerequest = " + get_xconfigurerequest() +", ";
ret += ""+"xcirculate = " + get_xcirculate() +", ";
ret += ""+"xcirculaterequest = " + get_xcirculaterequest() +", ";
ret += ""+"xproperty = " + get_xproperty() +", ";
ret += ""+"xselectionclear = " + get_xselectionclear() +", ";
ret += ""+"xselectionrequest = " + get_xselectionrequest() +", ";
ret += ""+"xselection = " + get_xselection() +", ";
ret += ""+"xcolormap = " + get_xcolormap() +", ";
ret += ""+"xclient = " + get_xclient() +", ";
ret += ""+"xmapping = " + get_xmapping() +", ";
ret += ""+"xerror = " + get_xerror() +", ";
ret += ""+"xkeymap = " + get_xkeymap() +", ";
ret += "{" + get_pad(0) + " " + get_pad(1) + " " + get_pad(2) + " " +
get_pad(3) + " " + get_pad(4) + " " + get_pad(5) + " " + get_pad(6) + "
" + get_pad(7) + " " + get_pad(8) + " " + get_pad(9) + " " + get_pad(10)
+ " " + get_pad(11) + " " + get_pad(12) + " " + get_pad(13) + " " +
get_pad(14) + " " + get_pad(15) + " " + get_pad(16) + " " + get_pad(17)
+ " " + get_pad(18) + " " + get_pad(19) + " " + get_pad(20) + " " +
get_pad(21) + " " + get_pad(22) + " " + get_pad(23) + " " + "}";
return ret;
}