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) {
>>>
>>>
>>>
>>
>>
>
