Holger, you are right: PlatformLogger does not care about custom Level implementations because it relies on j.u.l.Logger to decide if the message should be logged or not:
609 public boolean isLoggable(int level) { 610 return LoggingSupport.isLoggable(javaLogger, getLevel(level)); 611 } The former Map<Integer, Object> levelObjects I removed was only used to get the j.u.l.Level instance corresponding to a PlatformLogger's level which are defined as int constants. FYI, the former map was filled with only j.u.l.Level instances corresponding to all PlatformLogger's levels: 481 private static void getLevelObjects() { 482 // get all java.util.logging.Level objects 483 int[] levelArray = new int[] {OFF, SEVERE, WARNING, INFO, CONFIG, FINE, FINER, FINEST, ALL}; 484 for (int l : levelArray) { 485 Object level = LoggingSupport.parseLevel(getLevelName(l)); 486 levelObjects.put(l, level); 487 } 488 } I think I did not change the scope of the mapping i.e. PlatformLogger's levels. Cheers, Laurent 2013/3/21 Laurent Bourgès <bourges.laur...@gmail.com> > Here is the test code that was scrubbed in my previous email. > > As you can see in my benchmarks: > - TLAB has a major impact on Integer allocation overhead > - patched code is 2x faster (with TLAB enabled) > > Test code: > > package test; > > import java.util.logging.Level; > import java.util.logging.Logger; > import sun.util.logging.LoggingSupport; > import sun.util.logging.PlatformLogger; > > /** > * PlatformLogger patch Test (performance / memory overhead) > * @author bourgesl > */ > public class PlatformLoggerTest { > > /** logger - enable java.util.logging to enable PlatformLogger using > JUL */ > private final static Logger logger = > Logger.getLogger(PlatformLoggerTest.class.getName()); > > public static void main(String[] args) { > > /* > * 1/ JVM options during tests: > * -Xms8m -Xmx8m -XX:-UseTLAB -XX:+PrintTLAB > * > * JDK7_13 results: > mars 21, 2013 11:15:07 AM test.PlatformLoggerTest main > INFO: PlatformLoggerTest: start on JVM1.7.0_13 [Java HotSpot(TM) > 64-Bit Server VM 23.7-b01] > * > INFO: testPerf[100000 iterations]: duration = 61.536460999999996 > ms. > INFO: PlatformLoggerTest: starting 100000000 iterations ... > INFO: testPerf[100000000 iterations]: duration = 10485.07581 ms. > INFO: testPerf[100000000 iterations]: duration = 10639.329926 ms. > INFO: testPerf[100000000 iterations]: duration = 10903.235198 ms. > INFO: testPerf[100000000 iterations]: duration = 10728.399372 ms. > INFO: testPerf[100000000 iterations]: duration = 10643.329983 ms. > INFO: testPerf[100000000 iterations]: duration = 10720.43687 ms. > INFO: testPerf[100000000 iterations]: duration = > 10864.371595999999 ms. > INFO: testPerf[100000000 iterations]: duration = 10713.845459 ms. > INFO: testPerf[100000000 iterations]: duration = 10458.257711 ms. > INFO: testPerf[100000000 iterations]: duration = 10606.267606 ms. > * > * OpenJDK8 (+patch): > mars 21, 2013 11:19:03 AM test.PlatformLoggerTest main > Infos: PlatformLoggerTest: start on JVM1.8.0-internal [OpenJDK > 64-Bit Server VM 25.0-b22] > * > Infos: testPerf[100000 iterations]: duration = 24.862816 ms. > Infos: PlatformLoggerTest: starting 100000000 iterations ... > Infos: testPerf[100000000 iterations]: duration = 1043.957166 ms. > Infos: testPerf[100000000 iterations]: duration = 1013.602486 ms. > Infos: testPerf[100000000 iterations]: duration = > 1018.2792629999999 ms. > Infos: testPerf[100000000 iterations]: duration = 1073.422125 ms. > Infos: testPerf[100000000 iterations]: duration = 1024.742149 ms. > Infos: testPerf[100000000 iterations]: duration = > 1021.3166339999999 ms. > Infos: testPerf[100000000 iterations]: duration = 1014.771751 ms. > Infos: testPerf[100000000 iterations]: duration = > 1017.6148959999999 ms. > Infos: testPerf[100000000 iterations]: duration = > 1021.4425389999999 ms. > Infos: testPerf[100000000 iterations]: duration = 1020.200104 ms. > * > * 2/ JVM options during tests: > * -Xms8m -Xmx8m -XX:+UseTLAB > * > * JDK7_13 results: > * mars 21, 2013 12:58:37 PM test.PlatformLoggerTest main > INFO: PlatformLoggerTest: start on JVM1.7.0_13 [Java HotSpot(TM) > 64-Bit Server VM 23.7-b01] > * > INFO: testPerf[100000 iterations]: duration = 55.329637 ms. > INFO: PlatformLoggerTest: starting 100000000 iterations ... > INFO: testPerf[100000000 iterations]: duration = 2553.872667 ms. > INFO: testPerf[100000000 iterations]: duration = 2327.072791 ms. > INFO: testPerf[100000000 iterations]: duration = 2324.000677 ms. > INFO: testPerf[100000000 iterations]: duration = > 2326.0859929999997 ms. > INFO: testPerf[100000000 iterations]: duration = 2325.34332 ms. > INFO: testPerf[100000000 iterations]: duration = 2322.579729 ms. > INFO: testPerf[100000000 iterations]: duration = 2322.170814 ms. > INFO: testPerf[100000000 iterations]: duration = 2324.055535 ms. > INFO: testPerf[100000000 iterations]: duration = > 2432.6784829999997 ms. > INFO: testPerf[100000000 iterations]: duration = 2335.47692 ms. > * > * OpenJDK8 (+patch): > mars 21, 2013 1:00:30 PM test.PlatformLoggerTest main > Infos: PlatformLoggerTest: start on JVM1.8.0-internal [OpenJDK > 64-Bit Server VM 25.0-b22] > * > Infos: testPerf[100000 iterations]: duration = 22.091089999999998 > ms. > Infos: PlatformLoggerTest: starting 100000000 iterations ... > Infos: testPerf[100000000 iterations]: duration = 1023.84232 ms. > Infos: testPerf[100000000 iterations]: duration = > 1010.5437909999999 ms. > Infos: testPerf[100000000 iterations]: duration = > 1004.6675389999999 ms. > Infos: testPerf[100000000 iterations]: duration = > 1005.2778669999999 ms. > Infos: testPerf[100000000 iterations]: duration = 1017.892527 ms. > Infos: testPerf[100000000 iterations]: duration = 1006.359113 ms. > Infos: testPerf[100000000 iterations]: duration = 1006.2957 ms. > Infos: testPerf[100000000 iterations]: duration = > 1008.3199189999999 ms. > Infos: testPerf[100000000 iterations]: duration = > 1001.7142339999999 ms. > Infos: testPerf[100000000 iterations]: duration = 997.141141 ms. > * > * That's all folks! > */ > > // JVM options: -Xms8m -Xmx8m -verbose:gc -XX:-UseTLAB > -XX:+PrintTLAB > > // Note: -XX:-UseTLAB because Thread local allocator is efficient > to support Integer allocations > > logger.info("PlatformLoggerTest: start on JVM" + > System.getProperty("java.version") + " [" + System.getProperty(" > java.vm.name") + " " + System.getProperty("java.vm.version") + "]"); > > > logger.info("PlatformLoggerTest: LoggingSupport.isAvailable() = " > + LoggingSupport.isAvailable()); > > PlatformLogger.redirectPlatformLoggers(); > > final PlatformLogger log = PlatformLogger.getLogger("sun.awt.X11"); > > log.setLevel(PlatformLogger.INFO); > > final boolean testEnabledLogs = false; > > logger.info("PlatformLogger: enabled = " + log.isEnabled()); > logger.info("PlatformLogger: level = " + log.getLevel()); > > /* > for (Enumeration<String> e = > LogManager.getLogManager().getLoggerNames(); e.hasMoreElements();) { > logger.info("PlatformLoggerTest: logger[" + e.nextElement() + > "]"); > } > */ > > // Cleanup before test: > cleanup(); > > > int nLog = 0; > > final int WARMUP = 100 * 1000; > > long start = System.nanoTime(); > > for (int i = 0; i < WARMUP; i++) { > > > if (log.isLoggable(PlatformLogger.FINEST)) { > log.finest("test PlatformLogger.FINEST"); > nLog++; // ensure hotspot do not skip isLoggable() > } else { > nLog--; > } > > if (log.isLoggable(PlatformLogger.FINE)) { > log.fine("test PlatformLogger.FINE"); > nLog++; // ensure hotspot do not skip isLoggable() > } else { > nLog--; > } > > if (log.isLoggable(PlatformLogger.FINER)) { > log.finer("test PlatformLogger.FINER"); > nLog++; // ensure hotspot do not skip isLoggable() > } else { > nLog--; > } > > if (log.isLoggable(PlatformLogger.CONFIG)) { > log.config("test PlatformLogger.CONFIG"); > nLog++; // ensure hotspot do not skip isLoggable() > } else { > nLog--; > } > > if (testEnabledLogs) { > if (log.isLoggable(PlatformLogger.INFO)) { > log.info("test PlatformLogger.INFO"); > nLog++; // ensure hotspot do not skip isLoggable() > } else { > nLog--; > } > > if (log.isLoggable(PlatformLogger.WARNING)) { > log.warning("test PlatformLogger.WARNING"); > nLog++; // ensure hotspot do not skip isLoggable() > } else { > nLog--; > } > > if (log.isLoggable(PlatformLogger.SEVERE)) { > log.severe("test PlatformLogger.SEVERE"); > nLog++; // ensure hotspot do not skip isLoggable() > } else { > nLog--; > } > > if (log.isLoggable(PlatformLogger.OFF)) { > log.severe("test PlatformLogger.OFF"); > nLog++; // ensure hotspot do not skip isLoggable() > } else { > nLog--; > } > } > } > > log.info("testPerf[" + WARMUP + " iterations]: duration = " + > (1e-6d * (System.nanoTime() - start)) + " ms."); > log.info("testPerf: nLog = " + nLog); > cleanup(); > > > final int PASS = 10; > final int N = 100 * 1000 * 1000; > logger.info("PlatformLoggerTest: starting " + N + " iterations > ..."); > > for (int j = 0; j < PASS; j++) { > nLog = 0; > start = System.nanoTime(); > > for (int i = 0; i < N; i++) { > > > if (log.isLoggable(PlatformLogger.FINEST)) { > log.finest("test PlatformLogger.FINEST"); > nLog++; // ensure hotspot do not skip isLoggable() > } else { > nLog--; > } > > if (log.isLoggable(PlatformLogger.FINE)) { > log.fine("test PlatformLogger.FINE"); > nLog++; // ensure hotspot do not skip isLoggable() > } else { > nLog--; > } > > if (log.isLoggable(PlatformLogger.FINER)) { > log.finer("test PlatformLogger.FINER"); > nLog++; // ensure hotspot do not skip isLoggable() > } else { > nLog--; > } > > if (log.isLoggable(PlatformLogger.CONFIG)) { > log.config("test PlatformLogger.CONFIG"); > nLog++; // ensure hotspot do not skip isLoggable() > } else { > nLog--; > } > > if (testEnabledLogs) { > if (log.isLoggable(PlatformLogger.INFO)) { > log.info("test PlatformLogger.INFO"); > nLog++; // ensure hotspot do not skip isLoggable() > } else { > nLog--; > } > > if (log.isLoggable(PlatformLogger.WARNING)) { > log.warning("test PlatformLogger.WARNING"); > nLog++; // ensure hotspot do not skip isLoggable() > } else { > nLog--; > } > > if (log.isLoggable(PlatformLogger.SEVERE)) { > log.severe("test PlatformLogger.SEVERE"); > nLog++; // ensure hotspot do not skip isLoggable() > } else { > nLog--; > } > > if (log.isLoggable(PlatformLogger.OFF)) { > log.severe("test PlatformLogger.OFF"); > nLog++; // ensure hotspot do not skip isLoggable() > } else { > nLog--; > } > } > } > > log.info("testPerf[" + N + " iterations]: duration = " + > (1e-6d * (System.nanoTime() - start)) + " ms."); > log.info("testPerf: nLog = " + nLog); > cleanup(); > } > > try { > Thread.sleep(1000l); > } catch (InterruptedException ie) { > logger.log(Level.SEVERE, "Interrupted", ie); > } > > logger.info("PlatformLoggerTest: exit."); > } > > /** > * Cleanup (GC + pause) > */ > private static void cleanup() { > // Perform GC: > System.gc(); > > // pause: > try { > Thread.sleep(100l); > } catch (InterruptedException ie) { > > } > } > } > > 2013/3/21 Laurent Bourgès <bourges.laur...@gmail.com> > >> Here is an improved patch tested on JDK7u13 and JDK8 internal build on my >> machine linux x64: >> http://jmmc.fr/~bourgesl/share/webrev-8010309/ >> >> FYI, I removed completely the Map<Integer, Object> levelObjects and used >> two arrays to perform the PlatformLogger's level (int) to j.u.l.Level >> mapping: >> >> I decided to keep it simple as possible (no enum ...) and used a switch >> case based on current level occurences: >> >> 510 /** >> 511 * Return the corresponding j.u.l.Level instance >> 512 * @param level PlatformLogger level as integer >> >> >> 513 * @return Object (j.u.l.Level instance) or null if no matching >> level >> 514 */ >> 515 private static Object getLevel(final int level) { >> 516 if (levelObjects == null) { >> >> 517 return null; >> >> 518 } >> 519 // higher occurences first (finest, fine, finer, info) >> 520 // based on isLoggable(level) calls (03/20/2013) >> 521 // in jdk project only (including generated sources) >> >> >> 522 switch (level) { >> 523 case FINEST : return levelObjects[IDX_FINEST]; // 116 >> + 2257 matches in generated files >> 524 case FINE : return levelObjects[IDX_FINE]; // 270 >> >> >> 525 case FINER : return levelObjects[IDX_FINER]; // 157 >> 526 case INFO : return levelObjects[IDX_INFO]; // 39 >> 527 case WARNING : return levelObjects[IDX_WARNING]; // 12 >> >> >> 528 case CONFIG : return levelObjects[IDX_CONFIG]; // 6 >> 529 case SEVERE : return levelObjects[IDX_SEVERE]; // 1 >> 530 case OFF : return levelObjects[IDX_OFF]; // 0 >> >> >> 531 case ALL : return levelObjects[IDX_ALL]; // 0 >> 532 default : return null; >> 533 } >> 534 } >> >> I enhanced the PlatformLoggerTest class also and figured out that TLAB >> optimized Integer allocations but I think the patch is still useful. >> >> Can you have a look to the patch ? >> Should I write a jtreg test (performance / GC issue) ? >> >> Cheers, >> Laurent >> >> >> 2013/3/20 Mandy Chung <mandy.ch...@oracle.com> >> >>> Hi Laurent, >>> >>> Thank you for signing the OCA. Your contribution is very welcome. You >>> can submit a patch for this bug (see [1]) to Core libraries group which >>> owns logging. Jim Gish and I will sponsor it. >>> >>> Thanks >>> Mandy >>> [1] http://openjdk.java.net/contribute/ >>> >>> >>> On 3/20/2013 5:45 AM, Laurent Bourgès wrote: >>> >>> Hi mandy, >>> >>> Do you want me to propose an improved patch to remove the former Map and >>> fix the getLevel() method ? or you prefer fix on your own ? >>> >>> Is it better to discuss the fix on the bug database (still not visible) ? >>> >>> Laurent >>> >>> 2013/3/19 Mandy Chung <mandy.ch...@oracle.com> >>> >>>> Hi Laurent, >>>> >>>> Thanks for the contribution. I agree that the map can be replaced with >>>> a direct mapping from a int value to Level object and avoid the autoboxing >>>> conversion. >>>> >>>> I have filed a bug to track this and target this for JDK8: >>>> http://bugs.sun.com/bugdatabase/view_bug.do?bug_id= 8010309 >>>> >>>> Thanks >>>> Mandy >>>> >>>> >>>> On 3/19/13 5:19 AM, 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 figured out a >>>> performance and waste issue related to PlatformLogger. >>>> >>>> Actually, the JavaLogger implementation uses a Map<Integer, Object> >>>> levelObjects to store mapping between PlatformLogger's levels (int) and JUL >>>> Level instances. >>>> >>>> However, the isLoggable(int level) method is highly used by awt project and >>>> other JDK projects and it leads to many Integer allocations as autoboxing >>>> converts the level as int to an Integer instance used by the Map.get() >>>> call. >>>> >>>> /** >>>> * JavaLogger forwards all the calls to its corresponding >>>> * java.util.logging.Logger object. >>>> */ >>>> static class JavaLogger extends LoggerProxy { >>>> private static final* Map<Integer, Object>* levelObjects = new >>>> HashMap<>(); >>>> ... >>>> public boolean isLoggable(*int level*) { >>>> return LoggingSupport.isLoggable(javaLogger, * >>>> levelObjects.get(level)*); >>>> } >>>> } >>>> >>>> I wrote a simple test to illustrate that performance / waste problem: >>>> PlatformLoggerTest that simply performs 1 million DISABLED log statements: >>>> if (log.isLoggable(PlatformLogger.FINEST)) { >>>> log.finest("test PlatformLogger.FINEST"); >>>> } >>>> >>>> As you can see in screenshots: >>>> - 5 million Integer instances are allocated >>>> - Integer.valueOf(int) is called 5 million times (autoboxing) >>>> - HashMap.get() represents 30% of the test time >>>> - patched PlatformLogger is 3x times faster >>>> [jvm options: -Xms8m -Xmx8m -verbose:gc] >>>> >>>> I suggest you to use an alternative way to map PlatformLogger's levels >>>> (int) and JUL Level instances to fix that performance / memory issue: I >>>> added the getLevel(int level) method that performs a switch case to return >>>> the corresponding Level object (quick and dirty solution). >>>> >>>> I advocate this is not a very clean solution but I prefer efficiency here: >>>> any better solution may be appropriate to avoid at least Integer allocation >>>> and maybe enhance performance. >>>> >>>> Best regards, >>>> Laurent Bourgès >>>> >>>> PS: here is the patch as text: >>>> >>>> # This patch file was generated by NetBeans IDE >>>> # It uses platform neutral UTF-8 encoding and \n newlines. >>>> --- PlatformLogger.java (6767) >>>> +++ PlatformLogger.java (6768) >>>> @@ -468,31 +468,13 @@ >>>> * java.util.logging.Logger object. >>>> */ >>>> static class JavaLogger extends LoggerProxy { >>>> - /** Note: using Integer keys leads to a lot of new Integer >>>> instances !! */ >>>> - private static final Map<Integer, Object> levelObjects = new >>>> HashMap<>(); >>>> - /** fastest mapping to Level instances from PlatformLogger level >>>> as integer */ >>>> - private static final Object[] fastLevelObjects; >>>> - >>>> - >>>> + private static final Map<Integer, Object> levelObjects = >>>> + new HashMap<>(); >>>> + >>>> static { >>>> if (LoggingSupport.isAvailable()) { >>>> // initialize the map to Level objects >>>> getLevelObjects(); >>>> - >>>> - // initialize the fastLevelObjects: >>>> - fastLevelObjects = new Object[] { >>>> - LoggingSupport.parseLevel(getLevelName(OFF)), // >>>> 0 >>>> - LoggingSupport.parseLevel(getLevelName(SEVERE)), // >>>> 1 >>>> - LoggingSupport.parseLevel(getLevelName(WARNING)), // >>>> 2 >>>> - LoggingSupport.parseLevel(getLevelName(INFO)), // >>>> 3 >>>> - LoggingSupport.parseLevel(getLevelName(CONFIG)), // >>>> 4 >>>> - LoggingSupport.parseLevel(getLevelName(FINE)), // >>>> 5 >>>> - LoggingSupport.parseLevel(getLevelName(FINER)), // >>>> 6 >>>> - LoggingSupport.parseLevel(getLevelName(FINEST)), // >>>> 7 >>>> - LoggingSupport.parseLevel(getLevelName(ALL)) // >>>> 8 >>>> - }; >>>> - } else { >>>> - fastLevelObjects = null; // check null >>>> } >>>> } >>>> >>>> @@ -515,7 +497,7 @@ >>>> this.javaLogger = LoggingSupport.getLogger(name); >>>> if (level != 0) { >>>> // level has been updated and so set the Logger's level >>>> - LoggingSupport.setLevel(javaLogger, getLevel(level)); >>>> + LoggingSupport.setLevel(javaLogger, >>>> levelObjects.get(level)); >>>> } >>>> } >>>> >>>> @@ -526,11 +508,11 @@ >>>> * not be updated. >>>> */ >>>> void doLog(int level, String msg) { >>>> - LoggingSupport.log(javaLogger, getLevel(level), msg); >>>> + LoggingSupport.log(javaLogger, levelObjects.get(level), msg); >>>> } >>>> >>>> void doLog(int level, String msg, Throwable t) { >>>> - LoggingSupport.log(javaLogger, getLevel(level), msg, t); >>>> + LoggingSupport.log(javaLogger, levelObjects.get(level), msg, >>>> t); >>>> } >>>> >>>> void doLog(int level, String msg, Object... params) { >>>> @@ -544,12 +526,12 @@ >>>> for (int i = 0; i < len; i++) { >>>> sparams [i] = String.valueOf(params[i]); >>>> } >>>> - LoggingSupport.log(javaLogger, getLevel(level), msg, sparams); >>>> + LoggingSupport.log(javaLogger, levelObjects.get(level), msg, >>>> sparams); >>>> } >>>> >>>> boolean isEnabled() { >>>> Object level = LoggingSupport.getLevel(javaLogger); >>>> - return level == null || level.equals(getLevel(OFF)) == false; >>>> + return level == null || level.equals(levelObjects.get(OFF)) == >>>> false; >>>> } >>>> >>>> int getLevel() { >>>> @@ -566,34 +548,12 @@ >>>> >>>> void setLevel(int newLevel) { >>>> levelValue = newLevel; >>>> - LoggingSupport.setLevel(javaLogger, getLevel(newLevel)); >>>> + LoggingSupport.setLevel(javaLogger, >>>> levelObjects.get(newLevel)); >>>> } >>>> >>>> public boolean isLoggable(int level) { >>>> - return LoggingSupport.isLoggable(javaLogger, getLevel(level)); >>>> + return LoggingSupport.isLoggable(javaLogger, >>>> levelObjects.get(level)); >>>> } >>>> - >>>> - /** >>>> - * Return the corresponding level object (fastest implementation) >>>> - * @param level PlatformLogger level as primitive integer >>>> - * @return Object (JUL Level instance) >>>> - */ >>>> - private static Object getLevel(final int level) { >>>> - // higher occurences first (finest, fine, finer, info): >>>> - switch (level) { >>>> - case FINEST : return fastLevelObjects[7]; >>>> - case FINE : return fastLevelObjects[5]; >>>> - case FINER : return fastLevelObjects[6]; >>>> - case INFO : return fastLevelObjects[3]; >>>> - case CONFIG : return fastLevelObjects[4]; >>>> - case WARNING : return fastLevelObjects[2]; >>>> - case SEVERE : return fastLevelObjects[1]; >>>> - case ALL : return fastLevelObjects[8]; >>>> - case OFF : return fastLevelObjects[0]; >>>> - default : return null; >>>> - } >>>> - } >>>> - >>>> } >>>> >>>> private static String getLevelName(int level) { >>>> >>>> >>>> >>> >>> >> >