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

Thu Oct 27 07:13:01 PDT 2011

Hi all,

I agree, fixing the root cause of the issue makes sense. I've just filed 
a new CR to cover this fix.

The XWrapperBase descendants are indeed all generated at build time, so 
we only need to fix the WrapperGenerator class itself.

The patch sent by Federico looks good to me. Thank you very much for 
another contribution!

--
best regards,
Anthony

On 10/27/11 08:03, Oleg Sukhodolsky wrote:
> If you do not see these classes in the repo then they are generated in
> build time.
> Unfortunately I do not have a repo right now so I can not check this :(
>
> Oleg.
>
> On Thu, Oct 27, 2011 at 2:05 AM, Federico Tello Gentile
> <federicotg at gmail.com>  wrote:
>> Here's a patch to use StringBuilder. It also sets an initial size to
>> reduce char[] copying when appending.
>>
>> I ran the generator locally and checked the generated code.
>>
>> As I don't know if those java files are generated on every build or if
>> they were generated just once with certain input files and committed to
>> the repo, I did not go any further.
>>
>> I hope it is at least a starting point.
>>
>> El jue, 27-10-2011 a las 00:14 +0400, Oleg Sukhodolsky escribió:
>>> Yep, you are right. It is a WrapperGenerator who should be fixed.
>>> And after that we need to regenerate all wrappers (if they are not
>>> generated during build).
>>>
>>> Oleg.
>>>
>>> On Wed, Oct 26, 2011 at 11:27 PM, Federico<federicotg at gmail.com>  wrote:
>>>> Almost all sun.awt.X11.XWrapperBase subclasses have similarly horrible
>>>> getFieldsAsString() implementations, but they are all automatically
>>>> generated (which is a relief as there was no human being actually
>>>> writing such code).
>>>>
>>>> They all say at the beginning:
>>>>
>>>> // This file is an automatically generated file, please do not edit
>>>> this file, modify the WrapperGenerator.java file instead !
>>>>
>>>> My guess is in file
>>>> /openjdk/jdk/src/solaris/classes/sun/awt/X11/generator/WrapperGenerator.java
>>>>
>>>> in line 678
>>>> public void writeToString(StructType stp, PrintWriter pw) {
>>>>
>>>> starts the code generating bit.
>>>>
>>>>
>>>> 2011/10/26 Oleg Sukhodolsky<son.two at gmail.com>:
>>>>> +1 to Artem.
>>>>>
>>>>> It is better to fix this too.
>>>>>
>>>>> Oleg.
>>>>>
>>>>> On Wed, Oct 26, 2011 at 7:34 PM, Artem Ananiev<artem.ananiev at oracle.com>  wrote:
>>>>>>
>>>>>> On 10/26/2011 7:26 PM, Anthony Petrov wrote:
>>>>>>>
>>>>>>> On 10/26/2011 7:12 PM, Artem Ananiev wrote:
>>>>>>>>
>>>>>>>> On 10/21/2011 4:00 PM, Anthony Petrov wrote:
>>>>>>>>>
>>>>>>>>> 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?
>>>>>>>
>>>>>>> I guess you really mean the XEvent.getFieldsAsString() here [1], right?
>>>>>>
>>>>>> Yes, exactly. Thanks for this correction.
>>>>>>
>>>>>>> Possibly. But with Federico's fix this method now only gets called when
>>>>>>> logging is enabled, and as such the impact of the issue is limited.
>>>>>>
>>>>>> I realize that. My point is that we just hide the problem, or make it less
>>>>>> visible, or make it appear less frequently - whatever you prefer. However,
>>>>>> the problematic code that contains char[] allocation is still in the
>>>>>> workspace, and we know how often people use the current code as a pattern
>>>>>> for future changes...
>>>>>>
>>>>>> Thanks,
>>>>>>
>>>>>> Artem
>>>>>>
>>>>>>> [1]
>>>>>>> http://mail.openjdk.java.net/pipermail/awt-dev/2011-October/001952.html
>>>>>>>
>>>>>>> --
>>>>>>> best regards,
>>>>>>> Anthony
>>>>>>>
>>>>>>>
>>>>>>>>
>>>>>>>> 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;
>>>>>>>>>> }
>>>>>>>>>>
>>>>>>>>>>
>>>>>>
>>>>>
>>>>
>>
>> --
>> Mi clave pública
>> http://keyserver.ubuntu.com:11371/pks/lookup?op=get&search=0x157673683A51700A
>>