<AWT Dev> sun.awt.X11.XEvent is creating 600 MB of char[] for no good reason

[Anthony Petrov]

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.

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;
> 	}
> 
>