<AWT Dev> <Swing Dev> sun.awt.X11 logs still using String + (waste)
Peter Levart
peter.levart at gmail.com
Mon Apr 8 09:00:29 UTC 2013
On 04/07/2013 07:11 PM, Laurent Bourgès wrote:
>
> Hi
>
> I started fixing All PlatformlLogger "bad" usages and I am fixing also
> many jul Logger usages without isLoggable ...
> That represents a lot of changes and a very boring job.
>
> I think sending a webrew tomorrow.
>
Hi Laurent,
Since you're already deep in the task, you might have a rough feeling
what part of such unguarded log statements are of the following type:
logger.[fine,info,...]("a message with {0} and {1} placeholders",
someArg1, someArg2);
where someArg1, ... are some values that are already present in the
context of the logging statement and don't have to be computed just for
satisfying the logging (not even boxing). Such usages could be
effectively optimized by adding some overloaded methods to
PlatformLogger that take 1, 2, 3, ... arguments:
class PlatformLogger {
...
public void finest(String msg, Object param1) {
if (isLoggable(Level.FINEST)) {
loggerProxy.doLog(Level.FINEST, msg, param1);
}
}
public void finest(String msg, Object param1, Object param2) {
if (isLoggable(Level.FINEST)) {
loggerProxy.doLog(Level.FINEST, msg, param1, param2);
}
}
public void finest(String msg, Object param1, Object param2, Object
param3) {
if (isLoggable(Level.FINEST)) {
loggerProxy.doLog(Level.FINEST, msg, param1, param2, param3);
}
}
...
This would effectively guard creation of the arguments array with an
isLoggable check for some common usages, eliminating the need to
explicitly guard such statements. Of course, the user would have to be
aware of when such unguarded logging statement is without overhead and
when not...
How do you feel about such API extension?
Regards, Peter
> Laurent
>
> Le 4 avr. 2013 14:08, "Laurent Bourgès" <bourges.laurent at gmail.com
> <mailto:bourges.laurent at gmail.com>> a écrit :
>
> 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
> <mailto: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>
> <mailto:bourges.laurent at gmail.com
> <mailto: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>
> <mailto:anthony.petrov at oracle.com
> <mailto: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/>
>
>
> 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>
> <mailto:anthony.petrov at oracle.com
> <mailto: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>>>>
>
>
> 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>>
>
> 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/%__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>>
> (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/%__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>>>.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>>>("");
>
>
> 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>
> <mailto:bourges.laurent at gmail.com
> <mailto: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>>>
> <mailto:bourges.laurent at gmail
> <mailto:bourges.laurent at gmail>.
> <mailto:bourges.laurent at gmail
> <mailto: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>>>>>
>
> 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>
> <mailto:bourges.laurent at gmail.com
> <mailto: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>>>
> <mailto:bourges.laurent at gmail
> <mailto:bourges.laurent at gmail>.
> <mailto:bourges.laurent at gmail
> <mailto: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>>>>>
>
> 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>>
>
>
> 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>
> <mailto:anthony.petrov at oracle.com
> <mailto: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>>>
> <mailto:anthony.petrov at oracle
> <mailto:anthony.petrov at oracle>.
> <mailto:anthony.petrov at oracle
> <mailto: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>>>>>
>
> 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