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