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

Wed Oct 26 21:03:26 PDT 2011

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
>