[jboss-jira] [JBoss JIRA] (LOGMGR-157) Provide faster alternative to SimpleDataFormat

[James Perkins (JIRA)]

    [ https://issues.jboss.org/browse/LOGMGR-157?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13447654#comment-13447654 ] 

James Perkins edited comment on LOGMGR-157 at 8/10/17 6:46 PM:
---------------------------------------------------------------

So I finally did some testing today and didn't really notice much of a difference. I used the pattern {{"%d %-5p [%c] (%t) %s%e%n"}}. Maybe I should test with just the date to keep it more simple, but the results below are from each type of formatter.

{code:title=SimpleDateFormat}
Benchmark                            Mode  Cnt     Score    Error  Units
PatternFormatterBenchmark.noCause    avgt  200   835.709 ± 12.675  ns/op
{code}

{code:title=ISO8601DateFormat}
Benchmark                            Mode  Cnt     Score    Error  Units
PatternFormatterBenchmark.noCause    avgt  200   790.064 ±  5.355  ns/op
{code}

{code:title=DateTimeFormatter}
Benchmark                            Mode  Cnt     Score    Error  Units
PatternFormatterBenchmark.noCause    avgt  200   873.482 ± 12.207  ns/op
{code}

The {{ISO8601DateFormat}} does appear to be a little faster, but IMO not significant enough to invest in the time of writing our own date formatter. FWIW the {{ISO8601DateFormat}} also has to use a {{ThreadLocal}} because it uses a {{java.util.Calendar}} internally.

It is possible though that using the new {{DateTimeFormatter}} makes sense as it wouldn't require a {{ThreadLocal}} so it would likely produce less garbage.


was (Author: jamezp):
So I finally did some testing today and didn't really notice much of a difference.

{code:title=SimpleDateFormat}
Benchmark                            Mode  Cnt     Score    Error  Units
PatternFormatterBenchmark.noCause    avgt  200   835.709 ± 12.675  ns/op
{code}

{code:title=ISO8601DateFormat}
Benchmark                            Mode  Cnt     Score    Error  Units
PatternFormatterBenchmark.noCause    avgt  200   790.064 ±  5.355  ns/op
{code}

{code:title=DateTimeFormatter}
Benchmark                            Mode  Cnt     Score    Error  Units
PatternFormatterBenchmark.noCause    avgt  200   873.482 ± 12.207  ns/op
{code}

The {{ISO8601DateFormat}} does appear to be a little faster, but IMO not significant enough to invest in the time of writing our own date formatter. FWIW the {{ISO8601DateFormat}} also has to use a {{ThreadLocal}} because it uses a {{java.util.Calendar}} internally.

It is possible though that using the new {{DateTimeFormatter}} makes sense as it wouldn't require a {{ThreadLocal}} so it would likely produce less garbage.

> Provide faster alternative to SimpleDataFormat
> ----------------------------------------------
>
>                 Key: LOGMGR-157
>                 URL: https://issues.jboss.org/browse/LOGMGR-157
>             Project: JBoss Log Manager
>          Issue Type: Enhancement
>          Components: core
>    Affects Versions: 2.0.6.Final
>            Reporter: Koen Janssens
>         Attachments: DateFormatPerformance.java
>
>
> Whenever a data or timestamp is included in the logging pattern, SimpleDataFormat is used for formatting. Even with one instance per thread, it is still a heavy beast. 
> Other logging libraries (like the 15 year old log4j) have 'fast tracks' for known formats such as ISO 8601. These implementations are faster and generate less memory garbage. 
> During profiling, i discovered that simpledateformat is doing a lot of stuff while printing a date: 
> 	at java.lang.Thread.run(Thread.java:748)
> 	at org.jboss.logmanager.handlers.AsyncHandler$AsyncTask.run(AsyncHandler.java:196)
> 	at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:76)
> 	at org.jboss.logmanager.handlers.WriterHandler.doPublish(WriterHandler.java:46)
> 	at org.jboss.logmanager.ExtFormatter.format(ExtFormatter.java:32)
> 	at org.jboss.logmanager.formatters.MultistepFormatter.format(MultistepFormatter.java:83)
> 	at org.jboss.logmanager.formatters.Formatters$JustifyingFormatStep.render(Formatters.java:224)
> 	at org.jboss.logmanager.formatters.Formatters$5.renderRaw(Formatters.java:389)
> 	at java.text.DateFormat.format(DateFormat.java:345)
> 	at java.text.SimpleDateFormat.format(SimpleDateFormat.java:936)
> 	at java.text.SimpleDateFormat.format(SimpleDateFormat.java:966)
> 	at java.text.SimpleDateFormat.subFormat(SimpleDateFormat.java:1125)
> 	at java.util.Calendar.getDisplayName(Calendar.java:2110)
> 	at java.text.DateFormatSymbols.getInstance(DateFormatSymbols.java:340)
> 	at java.text.DateFormatSymbols.getProviderInstance(DateFormatSymbols.java:364)
> 	at sun.util.locale.provider.DateFormatSymbolsProviderImpl.getInstance(DateFormatSymbolsProviderImpl.java:85)
> 	at java.text.DateFormatSymbols.<init>(DateFormatSymbols.java:145)
> 	at java.text.DateFormatSymbols.initializeData(DateFormatSymbols.java:710)
> 	at sun.util.resources.LocaleData.getDateFormatData(LocaleData.java:127)
> 	at sun.util.resources.LocaleData.getBundle(LocaleData.java:163)
> 	at java.security.AccessController.doPrivileged(Native Method)
> 	at sun.util.resources.LocaleData$1.run(LocaleData.java:163)
> 	at sun.util.resources.LocaleData$1.run(LocaleData.java:167)
> 	at java.util.ResourceBundle.getBundle(ResourceBundle.java:890)
> 	at java.util.ResourceBundle.getBundleImpl(ResourceBundle.java:1348)
> 	at java.util.ResourceBundle.checkList(ResourceBundle.java:1400)
> 	at java.util.Collections$UnmodifiableCollection.isEmpty(Collections.java:1031)
> 	at java.util.AbstractCollection.isEmpty(AbstractCollection.java:86)
> I have attached a small comparision between simpledateformat performance and log4j ISO formatting performance. It roughly a factor 10 'faster'



--
This message was sent by Atlassian JIRA
(v7.2.3#72005)