sun.awt.X11 logs still using String + (waste) (original) (raw)

Anthony Petrov anthony.petrov at oracle.com
Tue Apr 9 06:08:35 PDT 2013

Hi Laurent,

Thanks for all your hard work! The fix looks fine to me.

I'm also CC'ing jdk8-dev@ to let other teams review the changes in their areas. I've only reviewed the AWT part of the fix.

-- best regards, Anthony

On 4/8/2013 15:32, Laurent Bourgès wrote:

Anthony,

here is an updated patch concerning both PlatformLogger and Logger 'bad' usages: http://jmmc.fr/~bourgesl/share/webrev-8010297.3/ It impacts now awt, swing, JMX, security, network, and apache xml. Thanks for the review, Laurent 2013/4/8 Laurent Bourgès <bourges.laurent at gmail.com_ _<mailto:bourges.laurent at gmail.com>> Peter, Mandy, I think it would be great to make PlatformLogger very similar to Logger API: I mean JUL Logger already has only 1 convenient method with 1 param so it may be great to have the same API in PlatformLogger too: maybe extend it to 2 or 3 params ... Peter, could you look at the API differences between Logger / PlatformLogger to make PlatformLogger API more similar to JUL Logger ? Laurent

2013/4/8 Peter Levart <peter.levart at gmail.com_ _<mailto:peter.levart at gmail.com>> 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/viewbug.__do?bugid=8010297 <http://bugs.sun.com/viewbug._do?bugid=8010297> <http://bugs.sun.com/viewbug._do?bugid=8010297_ _<http://bugs.sun.com/viewbug.do?bugid=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/viewbug.__do?bugid=8010297 <http://bugs.sun.com/viewbug._do?bugid=8010297> <http://bugs.sun.com/viewbug._do?bugid=8010297_ _<http://bugs.sun.com/viewbug.do?bugid=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 slog = (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: " + selectionowner); *} void addTrayIcon(XTrayIconPeer tiPeer) throws AWTException { ... * log.fine(" send SYSTEMTRAYREQUESTDOCK message to owner: " + selectionowner); *} 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 jdk8-dev mailing list