Bug 48778 - LogMF performs slower than SLF4J in benchmark
LogMF performs slower than SLF4J in benchmark
Status: RESOLVED FIXED
Product: Log4j
Classification: Unclassified
Component: Layout
1.2
PC Mac OS X 10.4
: P2 normal
: ---
Assigned To: log4j-dev
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2010-02-19 14:08 UTC by Curt Arnold
Modified: 2011-02-03 14:46 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Curt Arnold 2010-02-19 14:08:08 UTC
Initially reported in http://marc.info/?l=log4j-dev&m=122893058812874&w=2

This reason for the disparity has not been determined.  I would suspect that passing an int as the parameter might trigger some more expensive localized formatting than the equivalent SLF4J call.  It would be interesting to retry the benchmark using a String instead of an int to see if the effect is dependent on the type of the parameter.  Any profiling would also be helpful to determine the source of the performance difference.
Comment 1 Curt Arnold 2010-02-19 14:23:14 UTC
Earlier benchmarks referenced in thread referenced in original bug report.

http://marc.info/?l=log4j-dev&m=113719664927002&w=2
http://marc.info/?l=log4j-dev&m=113753508714633&w=2

I think these are more concerned about the performance difference between

LogSF.info(logger,"A {} rang out", "bell");

and


LogMF.info(logger,"A {0} rang out", "bell");


However, it would be good to review.
Comment 2 Curt Arnold 2010-03-14 01:50:00 UTC
The performance different does appear to be specific to requests that contain either a Number or a Date as a parameter.

The bottleneck fragment  was:

                    if (arg0 instanceof String) {
                        replacement = arg0.toString();
                    } else if (arg0 instanceof Number) {
                        replacement = NumberFormat.getInstance().format(arg0);
                    } else if (arg0 instanceof Date) {
                        replacement = DateFormat.getDateTimeInstance(
                                DateFormat.SHORT,
                                DateFormat.SHORT).format(arg0);
                    } else {
                        replacement = String.valueOf(arg0);
                    }

If the formatted value was a Integer, the call to NumberFormat.getInstance() took 75% of the time in format(), while NumberFormat.format() took 16%.  All the other code in this section was negligible.

Caching the result from NumberFormat.getInstance() eliminated the per-call hit for NumberFormat.getInstance() though it is still expensive the first time the formatter is obtained without any detectable per-call hit for the synchronization.

The call to NumberFormat.format() is roughly 5 times more expensive than the functionally equivalent call to String.valueOf().  The functions appear to return the same string for smaller integers, however they return different formatted values for doubles.  The committed code uses the cached NumberFormat if the parameter is a double or float and falls through to String.valueOf() for the other number types.  It is possible this results in LogMF not returning exactly the same formatted string as MessageFormat for some values or for some locales, but it seems like a reasonable optimization.

Date's had a similar performance profile, the call to DateFormat.getDateTimeInstance() was 85% of time in format(), 12% of time was spent in DateFormat.format().  String.valueOf() does not return the same value as DateFormat or MessageFormatter, so any date type is handled by DateFormat. 

When recreated the original benchmark report before the changes, I got:

LogMF (old): 3632
LogMF (new): 501 
SLF4J: 748
LogSF: 720

Replacing Integer x with String x:

LogMF (old): 321
LogMF (new): 272
SLF4J: 510
LogSF: 628

Replacing Integer x with Date x:

LogMF (old): 7212
LogMF (new): 2340
SLF4J: 834
LogSF: 1067

Replacing Integer x with Double x:

LogMF (old): 4585
LogMF (new): 1232
SLF4J: 1001
LogSF: 567

 
new = rev 922699
old = rev 922698


While there are other enhancements I expect to do on LogMF and LogSF shortly, caching NumberFormats and DateFormats gets LogMF comparable to SLF4J except for dates and doubles which should be rare enough that the hit is tolerable.  If it isn't, you can always use LogSF for those calls.
Comment 3 Xiaoming Shi 2011-02-03 14:46:02 UTC
Hi dude,

I find that this problem can be found in many other Apache Projects.

NumberFormat.getInstance:
 ./hadoop-0.21.0/mapred/src/java/org/apache/hadoop/mapred/FileOutputFormat.java line: 285
./pig-0.8.0/contrib/piggybank/java/src/main/java/org/apache/pig/piggybank/storage/MultiStorage.java line: 241
./apache-oodt-0.1-incubating-src/workflow/src/main/java/org/apache/oodt/cas/workflow/lifecycle/WorkflowLifecycleManager.java  line: 146
./apache-nutch-1.2/src/java/org/apache/nutch/util/TimingUtil.java   line: 44
./apache-ofbiz-10.04/framework/webapp/src/org/ofbiz/webapp/taglib/FormatTag.java   line: 78

DateFormat.getDateTimeInstance
./hadoop-0.21.0/hdfs/src/java/org/apache/hadoop/hdfs/server/balancer/Balancer.java   line:1520
./jackrabbit-2.2.2/jackrabbit-core/src/main/java/org/apache/jackrabbit/core/observation/EventJournalImpl.java   line:356  It’s in the critical section, so it’s more serious

./apache-ant-1.8.2/src/main/org/apache/tools/ant/taskdefs/Touch.java line:75
it uses a factory to generate the date format, and each time a date format is created
./apache-ant-1.8.2/src/main/org/apache/tools/ant/types/resources/selectors/Date.java  line: 141
./apache-ant-1.8.2/src/main/org/apache/tools/ant/types/selectors/DateSelector.java line :214
./apache-ant-1.8.2/src/main/org/apache/tools/ant/DefaultLogger.java  line:365
./apache-lenya-2.0.3-src/externals/cocoon_2_1_x/src/blocks/profiler/java/org/apache/cocoon/generation/ProfilerGenerator.java line:191
./apache-lenya-2.0.3-src/externals/cocoon_2_1_x/src/java/org/apache/cocoon/generation/StatusGenerator.java   line:255
./apache-ofbiz-10.04/framework/base/src/org/ofbiz/base/util/UtilDateTime.java line:702
./apache-ofbiz-10.04/framework/base/src/org/ofbiz/base/util/UtilFormatOut.java line:314
./openwebbeans-1.0.0/webbeans-impl/src/main/java/org/apache/webbeans/util/ClassUtil.java line: 1598
./apache-pivot-2.0-src/tutorials/src/org/apache/pivot/tutorials/stocktracker/StockTrackerWindow.java  line:363
./apache-pivot-2.0-src/wtk-terra/src/org/apache/pivot/wtk/skin/terra/TerraFileBrowserSkin.java 
line:281


(In reply to comment #0)
> Initially reported in http://marc.info/?l=log4j-dev&m=122893058812874&w=2
> 
> This reason for the disparity has not been determined.  I would suspect that
> passing an int as the parameter might trigger some more expensive localized
> formatting than the equivalent SLF4J call.  It would be interesting to retry
> the benchmark using a String instead of an int to see if the effect is
> dependent on the type of the parameter.  Any profiling would also be helpful to
> determine the source of the performance difference.