<AWT Dev> <Swing Dev> sun.awt.X11 logs still using String + (waste)
Laurent Bourgès
bourges.laurent at gmail.com
Thu Apr 4 12:08:29 UTC 2013
Ok, I can provide an updated patch after finding / fixing all usages.
Probably in 1 or 2 days,
Laurent
2013/4/4 Anthony Petrov <anthony.petrov at oracle.com>
> Yes, this makes sense. Do you want to update your fix for 8010297 to
> include these changes as well?
>
> --
> best regards,
> Anthony
>
>
> On 04/04/13 15:47, Laurent Bourgès wrote:
>
>> Dear all,
>>
>> I just realized there is another problem with PlatformLogger log
>> statements:
>> XBaseWindow:
>> public boolean grabInput() {
>> grabLog.fine("Grab input on {0}", this);
>> ...
>> }
>>
>> This calls the PlatformLogger.fine( varargs):
>> public void fine(String msg, Object... params) {
>> logger.doLog(FINE, msg, params);
>> }
>>
>> Doing so, the JVM creates a new Object[] instance to provide params as
>> varargs.
>>
>> I would recommend using isLoggable() test to avoid such waste if the log
>> is disabled (fine, finer, finest ...).
>>
>> Do you want me to provide a new patch related to this problem ?
>>
>> Does somebody have an idea to automatically analyze the JDK code and
>> detect missing isLoggable statements ...
>>
>> Regards,
>> Laurent
>>
>> 2013/4/3 Laurent Bourgès <bourges.laurent at gmail.com
>> <mailto:bourges.laurent at gmail.**com <bourges.laurent at gmail.com>>>
>>
>>
>> Anthony,
>>
>> could you tell me once it is in the OpenJDK8 repository ?
>> I would then perform again profiling tests to check if there is no
>> more missing isLoggable() statements.
>>
>> Once JMX and other projects switch to PlatformLogger, I could check
>> again.
>>
>> Maybe I could write a small java code checker (pmd rule) to test if
>> there is missing isLoggable() statements wrapping PlatformLogger log
>> statements. Any idea about how to reuse java parser to do so ?
>>
>> Regards,
>>
>> Laurent
>>
>> 2013/4/2 Anthony Petrov <anthony.petrov at oracle.com
>> <mailto:anthony.petrov at oracle.**com <anthony.petrov at oracle.com>>>
>>
>>
>> Looks fine to me as well. Thanks for fixing this, Laurent.
>>
>> Let's wait a couple more days in case Net or Swing folks want to
>> review the fix. After that I'll push it to the repository.
>>
>> --
>> best regards,
>> Anthony
>>
>>
>> On 4/2/2013 15:35, Laurent Bourgès wrote:
>>
>> Here is the updated patch:
>> http://jmmc.fr/~bourgesl/__**share/webrev-8010297.2/<http://jmmc.fr/%7Ebourgesl/__share/webrev-8010297.2/>
>> <http://jmmc.fr/%7Ebourgesl/**share/webrev-8010297.2/<http://jmmc.fr/%7Ebourgesl/share/webrev-8010297.2/>
>> >
>>
>>
>> Fixed inconsistencies between FINE / FINER log statements:
>> - XScrollbarPeer
>> - XWindowPeer
>>
>> Laurent
>>
>> 2013/4/2 Anthony Petrov <anthony.petrov at oracle.com
>> <mailto:anthony.petrov at oracle.**com<anthony.petrov at oracle.com>
>> >
>> <mailto:anthony.petrov at oracle.**__com
>>
>> <mailto:anthony.petrov at oracle.**com<anthony.petrov at oracle.com>
>> >>>
>>
>>
>> 1. Sergey: I believe this is for purposes of better
>> formating the
>> log output and making it more readable by separating or
>> highlighting
>> some sections. I don't think this should be changed.
>>
>> 2. Laurent: can you please address this issue and send
>> us a new patch?
>>
>> --
>> best regards,
>> Anthony
>>
>>
>> On 4/1/2013 16:08, Sergey Bylokhov wrote:
>>
>>
>> Hi, Anthony
>> Only two comments:
>> 1 Why we need some special text in the log output
>> like "***" and
>> "###"
>> 2 XScrollbarPeer.java:
>>
>> + if
>> (log.isLoggable(____**PlatformLogger.FINEST)) {
>>
>>
>> + log.finer("KeyEvent on scrollbar: " +
>> event);
>> + }
>>
>>
>>
>> On 4/1/13 12:20 PM, Anthony Petrov wrote:
>>
>> Awt, Swing, Net engineers,
>>
>> Could anyone review the fix please? For your
>> convenience:
>>
>> Bug:
>> http://bugs.sun.com/view_bug._**___do?bug_id=8010297<http://bugs.sun.com/view_bug.____do?bug_id=8010297>
>> <http://bugs.sun.com/view_bug.**__do?bug_id=8010297<http://bugs.sun.com/view_bug.__do?bug_id=8010297>
>> >
>>
>> <http://bugs.sun.com/view_bug.**__do?bug_id=8010297<http://bugs.sun.com/view_bug.__do?bug_id=8010297>
>> <http://bugs.sun.com/view_bug.**do?bug_id=8010297<http://bugs.sun.com/view_bug.do?bug_id=8010297>
>> >>
>>
>> Fix:
>> http://cr.openjdk.java.net/~__**
>> __anthony/8-55-isLoggable-____**8010297.0/<http://cr.openjdk.java.net/%7E____anthony/8-55-isLoggable-____8010297.0/>
>> <http://cr.openjdk.java.net/%**7E__anthony/8-55-isLoggable-__
>> **8010297.0/<http://cr.openjdk.java.net/%7E__anthony/8-55-isLoggable-__8010297.0/>
>> >
>> <http://cr.openjdk.java.net/%_**_7Eanthony/8-55-isLoggable-__
>> **8010297.0/
>> <http://cr.openjdk.java.net/%**7Eanthony/8-55-isLoggable-**
>> 8010297.0/<http://cr.openjdk.java.net/%7Eanthony/8-55-isLoggable-8010297.0/>
>> >>
>>
>> -- best regards,
>> Anthony
>>
>> On 3/22/2013 2:26, Anthony Petrov wrote:
>>
>> Hi Laurent,
>>
>> The fix looks great to me. Thank you very
>> much.
>>
>> We still need at least one review, though.
>> Hopefully
>> net-dev@ and/or swing-dev@ folks might help
>> us out a bit.
>>
>> -- best regards,
>> Anthony
>>
>> On 3/20/2013 15:10, Anthony Petrov wrote:
>>
>> Hi Laurent,
>>
>> Thanks for the patch. I've filed a bug
>> at:
>> http://bugs.sun.com/view_bug._**___do?bug_id=8010297<http://bugs.sun.com/view_bug.____do?bug_id=8010297>
>> <http://bugs.sun.com/view_bug.**__do?bug_id=8010297<http://bugs.sun.com/view_bug.__do?bug_id=8010297>
>> >
>>
>>
>> <http://bugs.sun.com/view_bug.**__do?bug_id=8010297<http://bugs.sun.com/view_bug.__do?bug_id=8010297>
>> <http://bugs.sun.com/view_bug.**do?bug_id=8010297<http://bugs.sun.com/view_bug.do?bug_id=8010297>
>> >>
>> (should be available in a day or two)
>>
>> and published a webrev generated from
>> your patch at:
>> http://cr.openjdk.java.net/~__**
>> __anthony/8-55-isLoggable-____**8010297.0/<http://cr.openjdk.java.net/%7E____anthony/8-55-isLoggable-____8010297.0/>
>> <http://cr.openjdk.java.net/%**7E__anthony/8-55-isLoggable-__
>> **8010297.0/<http://cr.openjdk.java.net/%7E__anthony/8-55-isLoggable-__8010297.0/>
>> >
>> <http://cr.openjdk.java.net/%_**_7Eanthony/8-55-isLoggable-__
>> **8010297.0/
>> <http://cr.openjdk.java.net/%**7Eanthony/8-55-isLoggable-**
>> 8010297.0/<http://cr.openjdk.java.net/%7Eanthony/8-55-isLoggable-8010297.0/>
>> >>
>>
>>
>> I'm also copying swing-dev@ and
>> net-dev@ because the
>> fix affects those areas too. I myself
>> will review
>> the fix a bit later but am sending it
>> now for other
>> folks to take a look at it.
>>
>> On 3/19/2013 15:29, Laurent Bourgès
>> wrote:
>>
>> I am sorry I started modifying
>> PlatformLogger
>> and reverted changes to this class
>> as it is
>> another topic to be discussed
>> later: isLoggable
>> performance and waste due to
>> HashMap<Integer,
>> Level> leads to Integer allocations
>> (boxing).
>>
>>
>> I saw your message to core-libs-dev@,
>> so I just
>> dropped all changes to the
>> PlatformLogger from this
>> patch.
>>
>> Finally, I have another question
>> related to the
>> WrapperGenerator class: it
>> generates a lot of
>> empty log statements (XEvent):
>>
>> log
>> <http://grepcode.com/file/____**
>> repository.grepcode.com/java/_**___root/jdk/openjdk/6-b14/sun/**
>> ____awt/X11/XWrapperBase.java#**____XWrapperBase.0log<http://grepcode.com/file/____repository.grepcode.com/java/____root/jdk/openjdk/6-b14/sun/____awt/X11/XWrapperBase.java#____XWrapperBase.0log>
>> <http://grepcode.com/file/__**repository.grepcode.com/java/_*
>> *_root/jdk/openjdk/6-b14/sun/__**awt/X11/XWrapperBase.java#__**
>> XWrapperBase.0log<http://grepcode.com/file/__repository.grepcode.com/java/__root/jdk/openjdk/6-b14/sun/__awt/X11/XWrapperBase.java#__XWrapperBase.0log>
>> >
>>
>> <http://grepcode.com/file/__**repository.grepcode.com/java/_*
>> *_root/jdk/openjdk/6-b14/sun/__**awt/X11/XWrapperBase.java#__**
>> XWrapperBase.0log<http://grepcode.com/file/__repository.grepcode.com/java/__root/jdk/openjdk/6-b14/sun/__awt/X11/XWrapperBase.java#__XWrapperBase.0log>
>> <http://grepcode.com/file/**repository.grepcode.com/java/**
>> root/jdk/openjdk/6-b14/sun/**awt/X11/XWrapperBase.java#**
>> XWrapperBase.0log<http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/6-b14/sun/awt/X11/XWrapperBase.java#XWrapperBase.0log>
>> >>>.finest
>> <http://grepcode.com/file/____**
>> repository.grepcode.com/java/_**___root/jdk/openjdk/6-b14/**
>> java/____util/logging/Logger.**java#____Logger.finest%28java.**
>> lang.____String%29<http://grepcode.com/file/____repository.grepcode.com/java/____root/jdk/openjdk/6-b14/java/____util/logging/Logger.java#____Logger.finest%28java.lang.____String%29>
>> <http://grepcode.com/file/__**repository.grepcode.com/java/_*
>> *_root/jdk/openjdk/6-b14/java/_**_util/logging/Logger.java#__**
>> Logger.finest%28java.lang.__**String%29<http://grepcode.com/file/__repository.grepcode.com/java/__root/jdk/openjdk/6-b14/java/__util/logging/Logger.java#__Logger.finest%28java.lang.__String%29>
>> >
>>
>> <http://grepcode.com/file/__**repository.grepcode.com/java/_*
>> *_root/jdk/openjdk/6-b14/java/_**_util/logging/Logger.java#__**
>> Logger.finest%28java.lang.__**String%29<http://grepcode.com/file/__repository.grepcode.com/java/__root/jdk/openjdk/6-b14/java/__util/logging/Logger.java#__Logger.finest%28java.lang.__String%29>
>> <http://grepcode.com/file/**repository.grepcode.com/java/**
>> root/jdk/openjdk/6-b14/java/**util/logging/Logger.java#**
>> Logger.finest%28java.lang.**String%29<http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/6-b14/java/util/logging/Logger.java#Logger.finest%28java.lang.String%29>
>> >>>("");
>>
>>
>> Is it really useful to have such
>> statements ? I
>> would keep logs with non empty
>> messages only.
>>
>> See WrapperGenerator:753:
>> String s_log =
>>
>> (generateLog?"log.finest(\"\")**____;":"");
>>
>>
>>
>>
>> I believe they're used for log
>> formatting purposes
>> to separate numerous events in a log
>> (e.g. think of
>> mouse-move events - there can be
>> hundreds of them in
>> a raw).
>>
>>
>> Please note that the hg export format
>> is not that
>> useful unless you're assigned an
>> OpenJDK id already
>> (please see Dalibor's message for
>> details) because I
>> can't import it directly. So for the
>> time being you
>> could send just raw patches (i.e. the
>> output of hg
>> diff only - and there's no need to
>> commit your
>> changes in this case). Also, please
>> note that the
>> mailing lists strip attachments. The
>> reason I got it
>> is because I was listed in To: of your
>> message. So
>> when sending patches you can:
>> 1) post them inline, or
>> 2) attach them and add a person to To:
>> of your
>> message, or
>> 3) upload them somewhere on the web.
>> However, it would be best if you could
>> generate a
>> webrev for your changes and upload it
>> somewhere.
>> Currently this is the standard format
>> for reviewing
>> fixes in OpenJDK.
>>
>> -- best regards,
>> Anthony
>>
>>
>> Regards,
>> Laurent
>>
>>
>>
>> 2013/3/19 Laurent Bourgès
>> <bourges.laurent at gmail.com <mailto:bourges.laurent at gmail.**
>> com <bourges.laurent at gmail.com>>
>> <mailto:bourges.laurent at gmail.**__com
>> <mailto:bourges.laurent at gmail.**com<bourges.laurent at gmail.com>
>> >>
>> <mailto:bourges.laurent at gmail.
>> <mailto:bourges.laurent at gmail.**>____com
>>
>> <mailto:bourges.laurent at gmail.**__com
>> <mailto:bourges.laurent at gmail.**com<bourges.laurent at gmail.com>
>> >>>>
>>
>> Hi antony,
>>
>> FYI I started reviewing and
>> fixing all
>> PlatformLogger use cases (not
>> too many as I thought first)
>> mainly used by
>> awt / swing projects to
>> provide you a patch on latest
>> JDK8 source code:
>>
>> I am adding the log level check
>> when it is
>> missing:
>> if
>> (...log.isLoggable(____**PlatformLogger.xxx)) {
>>
>>
>> log...
>> }
>>
>> I will not change the String +
>> operations to
>> use the message format
>> syntax in this patch.
>>
>> Do you accept such patch /
>> proposed
>> contribution ?
>>
>> Regards,
>> Laurent
>>
>>
>> 2013/3/18 Laurent Bourgès
>> <bourges.laurent at gmail.com <mailto:bourges.laurent at gmail.**
>> com <bourges.laurent at gmail.com>>
>> <mailto:bourges.laurent at gmail.**__com
>> <mailto:bourges.laurent at gmail.**com<bourges.laurent at gmail.com>
>> >>
>> <mailto:bourges.laurent at gmail.
>> <mailto:bourges.laurent at gmail.**>____com
>>
>> <mailto:bourges.laurent at gmail.**__com
>> <mailto:bourges.laurent at gmail.**com<bourges.laurent at gmail.com>
>> >>>>
>>
>> Hi antony,
>>
>> 2 different things:
>> 1/ PlatformLogger was
>> patched (doLog
>> method) to avoid string
>> operations (message
>> formatting) for
>> disabled logs (patch
>> submiited on JDK8 and JDK7u):
>> http://mail.openjdk.java.net/_**
>> ___pipermail/jdk7u-dev/2012-__**__April/002751.html<http://mail.openjdk.java.net/____pipermail/jdk7u-dev/2012-____April/002751.html>
>> <http://mail.openjdk.java.net/**__pipermail/jdk7u-dev/2012-__
>> **April/002751.html<http://mail.openjdk.java.net/__pipermail/jdk7u-dev/2012-__April/002751.html>
>> >
>>
>>
>> <http://mail.openjdk.java.net/**__pipermail/jdk7u-dev/2012-__
>> **April/002751.html<http://mail.openjdk.java.net/__pipermail/jdk7u-dev/2012-__April/002751.html>
>> <http://mail.openjdk.java.net/**pipermail/jdk7u-dev/2012-**
>> April/002751.html<http://mail.openjdk.java.net/pipermail/jdk7u-dev/2012-April/002751.html>
>> >>
>>
>>
>> 2/ I looked 2 hours ago on
>> JDK7u AND
>> JDK8 source codes and both
>> still have:
>> - log statements WITHOUT
>> log level check
>> : if
>>
>> (log.isLoggable(____**PlatformLogger.FINE))
>>
>>
>> log.fine(...);
>> - string operations (+) in
>> log calls
>> that could be improved
>> using the message format
>> syntax (String
>> + args): for example,
>> avoid using
>> PlatformLogger.fine(String +
>> ...) in favor of using
>> PlatformLogger.fine(String
>> msg,
>> Object... params)
>>
>> I reported in my previous
>> mail several
>> cases where the
>> isLoggable() call is
>> missing and leads
>> to useless String
>> operations but also method
>> calls
>> (Component.paramString() for
>> example).
>>
>> Finally, I also provided
>> other possible
>> cases (using grep);
>> maybe there is a better
>> alternative to
>> find all occurences of
>> String operations in log
>> calls.
>>
>> Regards,
>> Laurent
>>
>> 2013/3/18 Anthony Petrov
>> <anthony.petrov at oracle.com <mailto:anthony.petrov at oracle.**
>> com <anthony.petrov at oracle.com>>
>> <mailto:anthony.petrov at oracle.**__com
>> <mailto:anthony.petrov at oracle.**com<anthony.petrov at oracle.com>
>> >>
>> <mailto:anthony.petrov at oracle.
>> <mailto:anthony.petrov at oracle.**>____com
>>
>> <mailto:anthony.petrov at oracle.**__com
>> <mailto:anthony.petrov at oracle.**com<anthony.petrov at oracle.com>
>> >>>>
>>
>> Hi Laurent,
>>
>> Normally we fix an
>> issue in JDK 8
>> first, and then back-port
>> the fix to a 7u
>> release. You're
>> saying that in JDK 8 the
>> problem isn't
>> reproducible anymore.
>> Can you please
>> investigate (using the
>> Mercurial
>> history log) what exact fix
>> resolved it in JDK 8?
>>
>> --
>> best regards,
>> Anthony
>>
>> On 03/18/13 15:09,
>> Laurent Bourgès
>> wrote:
>>
>> Dear all,
>>
>> I run recently
>> netbeans profiler
>> on my swing application
>> (Aspro2:
>> http://www.jmmc.fr/aspro) under
>> linux x64 platform and I
>> figured out
>> that a lot of
>> char[] instances
>> are coming from String +
>> operator called
>> by sun.awt.X11 code.
>>
>> I looked at
>> PlatformLogger
>> source code but found not way
>> to disable it
>> completely: maybe
>> an empty
>> logger implementation could
>> be interesting to
>> be used during
>> profiling or
>> normal use (not debugging).
>> Apparently JDK8
>> provides some
>> patchs to avoid String
>> creation when the
>> logger is disabled
>> (level).
>>
>> However, I looked
>> also to the
>> sun.awt code (jdk7u
>> repository) to see
>> the
>> origin of the
>> string allocations:
>> XDecoratedPeer:
>> public void
>> handleFocusEvent(XEvent xev) {
>> ...
>> *
>> focusLog.finer("Received focus event on shell:
>> " + xfe);
>> * }
>>
>> public boolean
>> requestWindowFocus(long time,
>> boolean
>> timeProvided) {
>> ...
>> *
>> focusLog.finest("Real native focused
>> window: " +
>>
>> realNativeFocusedWindow +
>> "\nKFM's focused window: " +
>> focusedWindow);
>> *...
>> *
>> focusLog.fine("Requesting focus to " + (this ==
>> toFocus ? "this
>> window" : toFocus));
>> *...
>> }
>>
>> XBaseWindow:
>> public void
>> xSetBounds(int
>> x, int y, int width, int
>> height) {
>> ...
>> *
>> insLog.fine("Setting
>> bounds on " + this + " to
>> (" + x + ", " +
>> y + "), " + width +
>> "x" + height);
>> *}
>>
>> XNetProtocol:
>> boolean
>> doStateProtocol() {
>> ...
>> *
>> stateLog.finer("______**doStateProtocol()
>> returns " +
>>
>>
>> res);
>> *}
>>
>> XSystemTrayPeer:
>>
>> XSystemTrayPeer(SystemTray
>> target) {
>> ...
>> * log.fine("
>> check if
>> system tray is available.
>> selection owner:
>> " + selection_owner);
>> *}
>> void
>> addTrayIcon(XTrayIconPeer tiPeer)
>> throws
>> AWTException {
>> ...
>> * log.fine("
>> send
>> SYSTEM_TRAY_REQUEST_DOCK
>> message to owner: " +
>> selection_owner);
>> *}
>>
>> XFramePeer:
>> public void
>> handlePropertyNotify(XEvent xev) {
>> ...
>>
>> stateLog.finer("State is the same: " +
>> state);
>> }
>>
>> However I only give
>> here few
>> cases but certainly others
>> are still
>> present in the
>> source code;
>> maybe findbugs or netbeans
>> warnings could
>> help you finding
>> all of them.
>>
>> I advocate the
>> amount of waste
>> (GC) is not very
>> important but String
>> conversion are also
>> calling
>> several toString() methods
>> that can be
>> costly (event,
>> Frame, window ...)
>>
>> Finally, I ran few
>> grep commands
>> on the sun.awt.X11 code
>> (jdk7u) and you
>> can look at them to
>> see all
>> string + operations related
>> to log statements.
>>
>> PS: I may help
>> fixing the source
>> code but I have no idea
>> how to
>> collaborate
>> (provide a patch ?)
>>
>> Regards,
>> Laurent Bourgès
>>
>>
>>
>>
>>
>>
>> -- Best regards, Sergey.
>>
>>
>>
>>
>>
More information about the core-libs-dev
mailing list