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

Mon Oct 31 07:48:17 PDT 2011

Hi Federico,

I've just pushed the follow-up fix to the JDK8 repository. As always, 
porting it to a 7 update release may take some time.

Thank you very much for another good contribution!

--
best regards,
Anthony

On 10/27/11 18:13, Anthony Petrov wrote:
> 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
>>>
>>>