Log4J Conversion Pattern Performance
I’ve seen the warnings before in log4j’s documentation about the format directives %C, %F, %L, %l and %M, which give really useful information, but at a cost. Well, what is the cost of using some of these settings? What if I use them all, or none? I just had to find out, here are the results:
These results completely reinforce the fact that the expensive settings %F, %L and %C should not be used in your production environment. In the unfortunate case that you use all of them, then you’re looking at ( already expensive ) logging calls taking 9 times longer, verging on millisecond timings.
Log4J Conversion Patterns
JVM Version 1.6.0_05-ea
Windows XP[x86] – 2 processors
5.46MB/63.56MB Memory
| Benchmark | Threads | Avg Nanos | Slow Factor |
|---|---|---|---|
| Fast | 1 | 28825.21 | 1.00x |
| Fast | 15 | 31416.34 | 1.09x |
| Fast | 20 | 32638.25 | 1.13x |
| Fast | 5 | 33509.15 | 1.16x |
| Fast | 10 | 33564.08 | 1.16x |
| Fast | 35 | 34246.23 | 1.19x |
| Fast | 50 | 36421.31 | 1.26x |
| Fast | 40 | 39088.55 | 1.36x |
| Fast | 30 | 39572.70 | 1.37x |
| Fast | 45 | 42566.97 | 1.48x |
| Fast | 25 | 44669.52 | 1.55x |
| %F:%L | 1 | 99596.84 | 3.46x |
| %C:%F:%L | 1 | 109776.19 | 3.81x |
| %F:%L | 15 | 120370.05 | 4.18x |
| %F:%L | 20 | 121903.60 | 4.23x |
| %F:%L | 5 | 122038.00 | 4.23x |
| %F:%L | 25 | 125623.38 | 4.36x |
| %F:%L | 35 | 126799.53 | 4.40x |
| %C:%F:%L | 10 | 127100.32 | 4.41x |
| %F:%L | 30 | 128148.09 | 4.45x |
| %F:%L | 40 | 128208.69 | 4.45x |
| %C:%F:%L | 20 | 131857.94 | 4.57x |
| %F:%L | 50 | 133799.33 | 4.64x |
| %F:%L | 10 | 133837.24 | 4.64x |
| %C:%F:%L | 25 | 134114.84 | 4.65x |
| %F:%L | 45 | 134969.59 | 4.68x |
| %C:%F:%L | 35 | 135091.85 | 4.69x |
| %C:%F:%L | 15 | 138423.94 | 4.80x |
| %C:%F:%L | 30 | 139919.54 | 4.85x |
| %C:%F:%L | 5 | 142347.28 | 4.94x |
| %C:%F:%L | 45 | 144215.52 | 5.00x |
| %C:%F:%L | 40 | 144652.90 | 5.02x |
| %C:%F:%L | 50 | 155159.06 | 5.38x |
| ALL | 45 | 260584.64 | 9.04x |
| ALL | 15 | 260779.51 | 9.05x |
| ALL | 40 | 263862.17 | 9.15x |
| ALL | 1 | 264690.88 | 9.18x |
| ALL | 25 | 266042.80 | 9.23x |
| ALL | 35 | 267562.76 | 9.28x |
| ALL | 5 | 270316.00 | 9.38x |
| ALL | 50 | 272006.58 | 9.44x |
| ALL | 10 | 276599.74 | 9.60x |
| ALL | 30 | 277064.42 | 9.61x |
| ALL | 20 | 286092.27 | 9.93x |
But, then, how long does the individual usage of the perpetrators cost? I ran that one, too. Here are the results:
%l is the most expensive conversion pattern. On average it takes an extra 140,000 nanoseconds.
%C is the next most expensive, taking about 110,000 nanoseconds longer.
The rest ( %M, %F, %L ) each take about 100,000 nanoseconds longer.
Now you know.
Log4J Conversion Patterns
Windows XP[x86] – 2 processors
4.94MB/63.56MB Memory
| Benchmark | Threads | Avg Nanos | Slow Factor |
|---|---|---|---|
| Fast | 30 | 33106.79 | 1.00x |
| Fast | 35 | 36082.72 | 1.09x |
| Fast | 20 | 37435.39 | 1.13x |
| Fast | 40 | 37615.85 | 1.14x |
| Fast | 10 | 40022.65 | 1.21x |
| Fast | 1 | 40961.19 | 1.24x |
| Fast | 25 | 41009.21 | 1.24x |
| Fast | 45 | 41631.96 | 1.26x |
| Fast | 50 | 42989.00 | 1.30x |
| Fast | 15 | 46050.36 | 1.39x |
| Fast | 5 | 50155.79 | 1.51x |
| %M | 5 | 126486.35 | 3.82x |
| %L | 15 | 132137.75 | 3.99x |
| %L | 35 | 134056.48 | 4.05x |
| %L | 40 | 134538.77 | 4.06x |
| %M | 15 | 135388.24 | 4.09x |
| %F | 10 | 137914.76 | 4.17x |
| %L | 5 | 138189.31 | 4.17x |
| %L | 25 | 138781.50 | 4.19x |
| %F | 15 | 139051.26 | 4.20x |
| %L | 10 | 139648.04 | 4.22x |
| %F | 25 | 139736.45 | 4.22x |
| %L | 20 | 140881.53 | 4.26x |
| %M | 10 | 140943.95 | 4.26x |
| %F | 20 | 142361.85 | 4.30x |
| %M | 20 | 142539.18 | 4.31x |
| %M | 25 | 142656.80 | 4.31x |
| %C | 20 | 143221.29 | 4.33x |
| %M | 30 | 143781.90 | 4.34x |
| %F | 5 | 143855.32 | 4.35x |
| %L | 30 | 144129.23 | 4.35x |
| %M | 40 | 144481.16 | 4.36x |
| %F | 35 | 145803.89 | 4.40x |
| %F | 30 | 145891.32 | 4.41x |
| %C | 10 | 147103.22 | 4.44x |
| %F | 45 | 148460.17 | 4.48x |
| %L | 45 | 148951.05 | 4.50x |
| %C | 25 | 149877.80 | 4.53x |
| %F | 50 | 150231.08 | 4.54x |
| %C | 30 | 150495.98 | 4.55x |
| %L | 50 | 151044.66 | 4.56x |
| %C | 5 | 151478.15 | 4.58x |
| %C | 35 | 151516.71 | 4.58x |
| %M | 45 | 152534.57 | 4.61x |
| %C | 15 | 152969.01 | 4.62x |
| %M | 50 | 152989.03 | 4.62x |
| %C | 50 | 154476.76 | 4.67x |
| %F | 40 | 155057.98 | 4.68x |
| %C | 45 | 155471.11 | 4.70x |
| %M | 35 | 155759.06 | 4.70x |
| %C | 40 | 165737.16 | 5.01x |
| %l | 10 | 170275.18 | 5.14x |
| %l | 5 | 172227.11 | 5.20x |
| %l | 20 | 172265.43 | 5.20x |
| %l | 35 | 174530.94 | 5.27x |
| %l | 50 | 175687.72 | 5.31x |
| %l | 45 | 177227.30 | 5.35x |
| %l | 15 | 177944.97 | 5.37x |
| %l | 30 | 177987.91 | 5.38x |
| %l | 25 | 181043.73 | 5.47x |
| %l | 40 | 186023.07 | 5.62x |
| %F | 1 | 203322.88 | 6.14x |
| %L | 1 | 209034.65 | 6.31x |
| %C | 1 | 218245.92 | 6.59x |
| %M | 1 | 222148.81 | 6.71x |
| %l | 1 | 223007.37 | 6.74x |
