8010309 : PlatformLogger: isLoggable performance / waste due to HashMap<Integer, Level> leads to Integer allocations (boxing)

Laurent Bourgès bourges.laurent at gmail.com
Thu Mar 21 12:05:27 UTC 2013


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.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[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.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/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) {
>>>
>>>
>>>
>>
>>
>



More information about the core-libs-dev mailing list