8010309 : PlatformLogger: isLoggable performance / waste due to HashMap<Integer, Level (original) (raw)

Laurent Bourgès bourges.laurent at gmail.com
Thu Mar 21 13:33:48 UTC 2013

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.laurent at 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 * * JDK713 results: mars 21, 2013 11:15:07 AM test.PlatformLoggerTest main INFO: PlatformLoggerTest: start on JVM1.7.013 [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 * * JDK713 results: * mars 21, 2013 12:58:37 PM test.PlatformLoggerTest main INFO: PlatformLoggerTest: start on JVM1.7.013 [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 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.laurent at 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[IDXFINEST]; // 116 + 2257 matches in generated files 524 case FINE : return levelObjects[IDXFINE]; // 270 525 case FINER : return levelObjects[IDXFINER]; // 157 526 case INFO : return levelObjects[IDXINFO]; // 39 527 case WARNING : return levelObjects[IDXWARNING]; // 12 528 case CONFIG : return levelObjects[IDXCONFIG]; // 6 529 case SEVERE : return levelObjects[IDXSEVERE]; // 1 530 case OFF : return levelObjects[IDXOFF]; // 0 531 case ALL : return levelObjects[IDXALL]; // 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.chung at 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.chung at 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/viewbug.do?bugid= 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) {

More information about the core-libs-dev mailing list