You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by GitBox <gi...@apache.org> on 2021/07/02 12:02:09 UTC
[GitHub] [logging-log4j2] sman-81 opened a new pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
sman-81 opened a new pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544
…rter for performance ~3x
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] sman-81 commented on a change in pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
sman-81 commented on a change in pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#discussion_r665523971
##########
File path: log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/NamePatternConverter.java
##########
@@ -29,6 +32,11 @@
*/
private final NameAbbreviator abbreviator;
+ /**
+ * Cache of previously encountered inputs (keys) and conversion results (values).
+ */
+ private final Map<String, String> conversionCache = new ConcurrentHashMap<>();
Review comment:
I could modify the PR to limit the cache to, let's say, 250 entries.
Applications that 'log normally' will benefit greatly.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] sman-81 commented on a change in pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
sman-81 commented on a change in pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#discussion_r666251291
##########
File path: log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/NamePatternConverter.java
##########
@@ -29,6 +32,11 @@
*/
private final NameAbbreviator abbreviator;
+ /**
+ * Cache of previously encountered inputs (keys) and conversion results (values).
+ */
+ private final Map<String, String> conversionCache = new ConcurrentHashMap<>();
Review comment:
Thanks for your feedback. I've added a system property to make the cache size configurable and updated the PR.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] sman-81 commented on pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
sman-81 commented on pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#issuecomment-893394475
Hi again @carterkozak interesting what you've found. Thanks for looking into this.
Your research puts a question mark behind the usefulness of my pull request.
My benchmarks were with a single thread only.
In practice, is this code executed in multiple log4j2 threads?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] jvz commented on pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
jvz commented on pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#issuecomment-1028315065
PRs are welcome; the PMC are all volunteers, though, who don't work on this project full time. Before each release, we usually go over open PRs and Jira issues to make sure to merge and close whatever is possible before making the release. The past few releases have been largely for security patches.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] sman-81 commented on pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
sman-81 commented on pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#issuecomment-1028224532
"we love pull requests" they say
you send them prs
you listen to their criticism
you incorporate their feedback
you think you're done
then nothing happens
forever
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] sman-81 edited a comment on pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
sman-81 edited a comment on pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#issuecomment-893394475
Hi again @carterkozak interesting what you've found. Thanks for looking into this.
Your research puts a question mark behind the usefulness of my pull request.
My benchmarks were with a single thread only.
In practice, is this code executed in multiple log4j2 threads?
My use case is millions of log records from the same logger (records that must be persisted for compliance reasons).
Ideally the abbreviated name of such a logger should be created once not millions of times, was my thought.
A cache (as exists in my PR) may not be the best solution.
The abbreviated name could be stored in the logger itself (all abbreviated names by pattern, to be precise), however this would require substantial architectural changes.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] vy commented on a change in pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
vy commented on a change in pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#discussion_r666004260
##########
File path: log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/NamePatternConverter.java
##########
@@ -29,6 +32,11 @@
*/
private final NameAbbreviator abbreviator;
+ /**
+ * Cache of previously encountered inputs (keys) and conversion results (values).
+ */
+ private final Map<String, String> conversionCache = new ConcurrentHashMap<>();
Review comment:
We can use the cache size property set to `0` to disable the cache.
##########
File path: log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/NamePatternConverter.java
##########
@@ -29,6 +32,11 @@
*/
private final NameAbbreviator abbreviator;
+ /**
+ * Cache of previously encountered inputs (keys) and conversion results (values).
+ */
+ private final Map<String, String> conversionCache = new ConcurrentHashMap<>();
Review comment:
We can use the cache size property set to `0` to disable the cache and have a sane default there.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] sman-81 commented on a change in pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
sman-81 commented on a change in pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#discussion_r681495858
##########
File path: log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/NamePatternConverter.java
##########
@@ -29,6 +32,11 @@
*/
private final NameAbbreviator abbreviator;
+ /**
+ * Cache of previously encountered inputs (keys) and conversion results (values).
+ */
+ private final Map<String, String> conversionCache = new ConcurrentHashMap<>();
Review comment:
`ping`
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] carterkozak commented on a change in pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
carterkozak commented on a change in pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#discussion_r665376798
##########
File path: log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/NamePatternConverter.java
##########
@@ -29,6 +32,11 @@
*/
private final NameAbbreviator abbreviator;
+ /**
+ * Cache of previously encountered inputs (keys) and conversion results (values).
+ */
+ private final Map<String, String> conversionCache = new ConcurrentHashMap<>();
Review comment:
I'm aware of applications which create an unbounded number of loggers using `LogManager.getLogger("resource." + resourceId)` to log a small amount of data. Such usage is expensive, and not good practice, but it shouldn't result in a memory leak.
I imagine if performance of abbreviation is a problem, we can improve that instead of adding caches. I'm generally a bit biased against using caches unless it's the only option, they're hard to monitor, maintain, debug, and reason about imo.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] sman-81 commented on a change in pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
sman-81 commented on a change in pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#discussion_r665971913
##########
File path: log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/NamePatternConverter.java
##########
@@ -29,6 +32,11 @@
*/
private final NameAbbreviator abbreviator;
+ /**
+ * Cache of previously encountered inputs (keys) and conversion results (values).
+ */
+ private final Map<String, String> conversionCache = new ConcurrentHashMap<>();
Review comment:
... or introduce a property that disables caching alltogether. I'm in favor of enabling it by default, otherwise most users will likely not benefit from it. In addition we limit the cache's size as a safeguard.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] sman-81 commented on a change in pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
sman-81 commented on a change in pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#discussion_r665525580
##########
File path: log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/NamePatternConverter.java
##########
@@ -29,6 +32,11 @@
*/
private final NameAbbreviator abbreviator;
+ /**
+ * Cache of previously encountered inputs (keys) and conversion results (values).
+ */
+ private final Map<String, String> conversionCache = new ConcurrentHashMap<>();
Review comment:
I did look at improving the abbreviation, but see little room without making code even less readable (the pattern support makes for rather complicated code already).
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] carterkozak commented on a change in pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
carterkozak commented on a change in pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#discussion_r670399057
##########
File path: log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/NamePatternConverter.java
##########
@@ -29,6 +32,11 @@
*/
private final NameAbbreviator abbreviator;
+ /**
+ * Cache of previously encountered inputs (keys) and conversion results (values).
+ */
+ private final Map<String, String> conversionCache = new ConcurrentHashMap<>();
Review comment:
Sorry, I’ve been backlogged lately and haven’t had a chance to investigate yet
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] vy commented on a change in pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
vy commented on a change in pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#discussion_r665369902
##########
File path: log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/NamePatternConverter.java
##########
@@ -29,6 +32,11 @@
*/
private final NameAbbreviator abbreviator;
+ /**
+ * Cache of previously encountered inputs (keys) and conversion results (values).
+ */
+ private final Map<String, String> conversionCache = new ConcurrentHashMap<>();
Review comment:
Using `CCM` for caching gives me the impression that this might have a memory impact in the long run. Though I need to dig further, I guess. @carterkozak, @jvz, @rgoers, @remkop, any ideas?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] sman-81 commented on a change in pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
sman-81 commented on a change in pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#discussion_r670376745
##########
File path: log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/NamePatternConverter.java
##########
@@ -29,6 +32,11 @@
*/
private final NameAbbreviator abbreviator;
+ /**
+ * Cache of previously encountered inputs (keys) and conversion results (values).
+ */
+ private final Map<String, String> conversionCache = new ConcurrentHashMap<>();
Review comment:
Hello @vy, how to proceed?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] sman-81 commented on pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
sman-81 commented on pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#issuecomment-948332250
As interest and progress are nil, I'll close the pull request end of this week.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] sman-81 closed pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
sman-81 closed pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] vy commented on a change in pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
vy commented on a change in pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#discussion_r665369902
##########
File path: log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/NamePatternConverter.java
##########
@@ -29,6 +32,11 @@
*/
private final NameAbbreviator abbreviator;
+ /**
+ * Cache of previously encountered inputs (keys) and conversion results (values).
+ */
+ private final Map<String, String> conversionCache = new ConcurrentHashMap<>();
Review comment:
Using `CHM` for caching gives me the impression that this might have a memory impact in the long run. Though I need to dig further, I guess. @carterkozak, @jvz, @rgoers, @remkop, any ideas?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] vy commented on a change in pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
vy commented on a change in pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#discussion_r665949982
##########
File path: log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/NamePatternConverter.java
##########
@@ -29,6 +32,11 @@
*/
private final NameAbbreviator abbreviator;
+ /**
+ * Cache of previously encountered inputs (keys) and conversion results (values).
+ */
+ private final Map<String, String> conversionCache = new ConcurrentHashMap<>();
Review comment:
@carterkozak, I totally agree with your remarks on the shortcomings of introducing a caching layer. Do you have any suggestions on how to improve the performance of the existing abbreviator?
This said, @sman-81's caching hack (with a bounded size) seems like a low hanging fruit to me. We need to introduce a property where one can change the default size. Further, shall we use a `CHM` or a `ReadWriteLock`-protected `HM`?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] carterkozak commented on pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
carterkozak commented on pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#issuecomment-893569664
> My benchmarks were with a single thread only.
In practice, is this code executed in multiple log4j2 threads?
As usual, the answer is “it depends” :-)
in the default configuration we log synchronously so that all formatting occurs on the application thread which calls into a logger, so contention is bounded by the total number of application threads which may interact with a logger. In most cases access to appender manager instances is guarded to prevent clobbering once the formatted buffer has been generated and must be written. However using asynchronous logging there’s generally one background thread responsible for executing layouts and writing log data to wherever it’s stored, in that case there shouldn’t be contention on the name abbreviator.
> The abbreviated name could be stored in the logger itself (all abbreviated names by pattern, to be precise), however this would require substantial architectural changes.
this would certainly be challenging given each logger would need to be aware of all the appenders and their layouts reachable in the configuration. With enough map lookups anything can become slow! Given how (relatively) fast abbreviation is, it’s very possible an attempted optimization would make real-world performance worse.
Do you have profiling data that shows abbreviation as a contributor to overall application congestion? I would imagine there would be many other components more likely to be the limiting factor.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] carterkozak commented on pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
carterkozak commented on pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#issuecomment-892137360
@sman-81 I've created a PR which aims to improve the worst-case performance of NameAbbreviator, however the the performance difference is smaller than I had anticipated: #555. Can you share some details about your use case to help me understand if this would be helpful?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [logging-log4j2] carterkozak commented on pull request #544: LOG4J2-3115: Remember previously computed strings in NamePatternConverter for performance ~3x
Posted by GitBox <gi...@apache.org>.
carterkozak commented on pull request #544:
URL: https://github.com/apache/logging-log4j2/pull/544#issuecomment-891993420
I slightly restructured the benchmark to fix the issue where only the first class was ever used, and reused the StringBuilder and LogEvent objects to avoid allocation overhead on a per-invocation basis.
## All benchmarks use 1 fork, 3 x 3 seconds warmup, 3*3 seconds measurement
I've run the benchmarks on an `Intel(R) Xeon(R) W-2175 CPU` with 14 cores and 28 threads.
### 1 thread
My results using the benchmark against release-2.x (no caching):
```
Benchmark (className) Mode Cnt Score Error Units
NamePatternConverterBenchmark.benchNamePatternConverter org.bogus.hokus.pokus.Clazz1 avgt 3 89.382 ± 3.264 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter com.bogus.hokus.pokus.Clazz2 avgt 3 91.734 ± 42.690 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter edu.bogus.hokus.pokus.a.Clazz3 avgt 3 98.898 ± 5.629 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter de.bogus.hokus.b.Clazz4 avgt 3 81.632 ± 1.608 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter jp.bogus.c.Clazz5 avgt 3 62.760 ± 2.325 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter cn.d.Clazz6 avgt 3 43.892 ± 2.879 ns/op
```
With the cache:
```
Benchmark (className) Mode Cnt Score Error Units
NamePatternConverterBenchmark.benchNamePatternConverter org.bogus.hokus.pokus.Clazz1 avgt 3 23.171 ± 4.225 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter com.bogus.hokus.pokus.Clazz2 avgt 3 22.009 ± 2.083 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter edu.bogus.hokus.pokus.a.Clazz3 avgt 3 22.745 ± 5.220 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter de.bogus.hokus.b.Clazz4 avgt 3 25.033 ± 4.682 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter jp.bogus.c.Clazz5 avgt 3 23.140 ± 6.582 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter cn.d.Clazz6 avgt 3 22.592 ± 4.511 ns/op
```
### 14 threads
My results using the benchmark against release-2.x (no caching):
```
Benchmark (className) Mode Cnt Score Error Units
NamePatternConverterBenchmark.benchNamePatternConverter org.bogus.hokus.pokus.Clazz1 avgt 3 108.224 ± 4.403 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter com.bogus.hokus.pokus.Clazz2 avgt 3 105.806 ± 7.577 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter edu.bogus.hokus.pokus.a.Clazz3 avgt 3 125.960 ± 3.303 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter de.bogus.hokus.b.Clazz4 avgt 3 101.220 ± 37.384 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter jp.bogus.c.Clazz5 avgt 3 78.575 ± 13.142 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter cn.d.Clazz6 avgt 3 54.714 ± 3.688 ns/op
```
With the cache:
```
Benchmark (className) Mode Cnt Score Error Units
NamePatternConverterBenchmark.benchNamePatternConverter org.bogus.hokus.pokus.Clazz1 avgt 3 8495.062 ± 9732.081 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter com.bogus.hokus.pokus.Clazz2 avgt 3 8920.030 ± 7984.602 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter edu.bogus.hokus.pokus.a.Clazz3 avgt 3 8843.975 ± 3125.221 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter de.bogus.hokus.b.Clazz4 avgt 3 8879.263 ± 4066.595 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter jp.bogus.c.Clazz5 avgt 3 8623.134 ± 3309.457 ns/op
NamePatternConverterBenchmark.benchNamePatternConverter cn.d.Clazz6 avgt 3 8833.953 ± 616.468 ns/op
```
## My interpretation:
Introducing a cache provides a synchronization point which didn't previously exist, so the worst case performance for a best-case cache (one with a single element that's always used due to the way benchmarks are broken up by fork) is substantially worse than the worst case performance of the uncached implementation.
The single threaded case sees an uplift of between 20ns and 80ns average time, while the multithreaded case sees an 8,500ns to 8,800ns potential regression (based on workload, hardware, etc).
I haven't benchmarked cases in which the cache is full and pointer jumps are required to find the matching element, nor cases in which we rotate through more loggers than we have cache space. I suspect an implementation using https://github.com/ben-manes/caffeine would work better as it supports several novel concurrent datastructures, and the cache size could be based on the length of input and output strings, but it would take a great deal of testing.
Benchmarks run with:
```java
package org.apache.logging.log4j.perf.jmh;
import org.apache.logging.log4j.core.AbstractLogEvent;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.pattern.LoggerPatternConverter;
import org.openjdk.jmh.annotations.Benchmark;
import org.openjdk.jmh.annotations.BenchmarkMode;
import org.openjdk.jmh.annotations.Fork;
import org.openjdk.jmh.annotations.Measurement;
import org.openjdk.jmh.annotations.Mode;
import org.openjdk.jmh.annotations.OutputTimeUnit;
import org.openjdk.jmh.annotations.Param;
import org.openjdk.jmh.annotations.Scope;
import org.openjdk.jmh.annotations.Setup;
import org.openjdk.jmh.annotations.State;
import org.openjdk.jmh.annotations.Threads;
import org.openjdk.jmh.annotations.Warmup;
import java.util.concurrent.TimeUnit;
/**
* Tests Log4j2 NamePatternConverter's performance.<br>
*
* How to run these benchmarks:<br>
*
* Single thread:<br>
* <pre>java -jar log4j-perf/target/benchmarks.jar ".*NamePatternConverterBenchmark.*" -f 1 -wi 2 -i 3 -r 3s -jvmArgs '-server -XX:+AggressiveOpts'</pre>
*
* Multiple threads (for example, 4 threads):<br>
* <pre>java -jar log4j-perf/target/benchmarks.jar ".*NamePatternConverterBenchmark.*" -f 1 -wi 4 -i 20 -t 4 -si true</pre>
*
* Usage help:<br>
* <pre>java -jar log4j-perf/target/benchmarks.jar -help</pre>
*/
@Fork(1)
@Threads(14)
@Warmup(iterations = 3, time = 3)
@Measurement(iterations = 3, time = 3)
public class NamePatternConverterBenchmark {
@State(Scope.Benchmark)
public static class ExecutionPlan {
@Param({
"org.bogus.hokus.pokus.Clazz1",
"com.bogus.hokus.pokus.Clazz2",
"edu.bogus.hokus.pokus.a.Clazz3",
"de.bogus.hokus.b.Clazz4",
"jp.bogus.c.Clazz5",
"cn.d.Clazz6"
})
String className;
LogEvent event;
private final ThreadLocal<StringBuilder> destination = ThreadLocal.withInitial(StringBuilder::new);
final LoggerPatternConverter converter = LoggerPatternConverter.newInstance(new String[] {"1."});
@Setup
public void setup() {
event = new BenchmarkLogEvent(className);
}
StringBuilder destination() {
StringBuilder result = destination.get();
result.setLength(0);
return result;
}
}
@Benchmark
@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
public void benchNamePatternConverter(ExecutionPlan plan) {
plan.converter.format(plan.event, plan.destination());
}
private static class BenchmarkLogEvent extends AbstractLogEvent {
private final String loggerName;
BenchmarkLogEvent(String loggerName) {
this.loggerName = loggerName;
}
@Override
public String getLoggerName() {
return loggerName;
}
}
}
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org