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.
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.
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.
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.