You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by cakofony <gi...@git.apache.org> on 2018/10/11 14:45:04 UTC
[GitHub] logging-log4j2 pull request #218: [LOG4J2-2475] More efficient parameter res...
GitHub user cakofony opened a pull request:
https://github.com/apache/logging-log4j2/pull/218
[LOG4J2-2475] More efficient parameter reset for reusable messages
Pushing to GH for feedback.
You can merge this pull request into a Git repository by running:
$ git pull https://github.com/cakofony/logging-log4j2 parameter_clearing
Alternatively you can review and apply these changes as the patch at:
https://github.com/apache/logging-log4j2/pull/218.patch
To close this pull request, make a commit to your master/trunk branch
with (at least) the following in the commit message:
This closes #218
----
commit d3c587ce3dcf107a4bc3ad66c0c926e662d0c63d
Author: Carter Kozak <ck...@...>
Date: 2018-10-11T11:04:50Z
[LOG4J2-2475] More efficient parameter reset for reusable messages
----
---
[GitHub] logging-log4j2 issue #218: [LOG4J2-2475] More efficient parameter reset for ...
Posted by cakofony <gi...@git.apache.org>.
Github user cakofony commented on the issue:
https://github.com/apache/logging-log4j2/pull/218
n=1000
```
Benchmark Mode Cnt Score Error Units
ManyParametersInSetupBenchmark.fewParameters thrpt 3 1406346.075 ± 82926.012 ops/s
```
n=100
```
Benchmark Mode Cnt Score Error Units
ManyParametersInSetupBenchmark.fewParameters thrpt 3 4332639.602 ± 232499.236 ops/s
```
n=10
```
Benchmark Mode Cnt Score Error Units
ManyParametersInSetupBenchmark.fewParameters thrpt 3 5480582.409 ± 1238380.733 ops/s
```
And another run with this change
```
Benchmark Mode Cnt Score Error Units
ManyParametersInSetupBenchmark.fewParameters thrpt 3 5814710.334 ± 899317.421 ops/s
```
---
[GitHub] logging-log4j2 issue #218: [LOG4J2-2475] More efficient parameter reset for ...
Posted by garydgregory <gi...@git.apache.org>.
Github user garydgregory commented on the issue:
https://github.com/apache/logging-log4j2/pull/218
One "realistic" example would be to think of logging against a database
table. Some tables have lots of columns. How many, well, a thousand is
possible I suppose.
Gary
On Tue, Oct 16, 2018 at 3:55 PM Remko Popma <no...@github.com>
wrote:
> I cannot imagine any program logging one million parameters so this
> benchmark is perhaps a bit academic. :-)
> In a realistic program a "large" parameter array is probably more like 100
> elements (and I would not like to maintain a program that has a logging
> statement with 100 parameters).
>
> Can we measure again with an extreme case of 1000 parameters?
>
> I suspect that with an array of 1000 (or even 10,000) elements we won't
> see much difference between nulling out only the first 10 or the full
> array, in which case it is more robust to simply null out the whole array.
>
> —
> You are receiving this because you are subscribed to this thread.
> Reply to this email directly, view it on GitHub
> <https://github.com/apache/logging-log4j2/pull/218#issuecomment-430415191>,
> or mute the thread
> <https://github.com/notifications/unsubscribe-auth/ABIfN3imZy0sRPYKZXh5-8f_Wi3aJ2Wjks5ullXigaJpZM4XXtEW>
> .
>
---
[GitHub] logging-log4j2 issue #218: [LOG4J2-2475] More efficient parameter reset for ...
Posted by cakofony <gi...@git.apache.org>.
Github user cakofony commented on the issue:
https://github.com/apache/logging-log4j2/pull/218
In most cases, I don't think this will make much difference because setting all 10 spots in a the reusable parameter buffer is incredibly fast.
This aims to solve problems that arise when a larger parameter array is passed to a logger, since that array will be reused and passed between MutableLogEvent (or RingBufferLogEvent) and ReusableParameterizedMessage. I don't want to discard parameter arrays above a given threshold because there are scenarios where we would want to allow them to be reused, but we also don't want to iterate over each index and set it to null if we know there's only a single parameter.
I've put together a simple benchmark to illustrate performance implications. It's fairly contrived, close to the worst case scenario.
Without this change:
```
Benchmark Mode Cnt Score Error Units
ManyParametersInSetupBenchmark.fewParameters thrpt 3 1706.636 ± 89.416 ops/s
```
With this change:
```
Benchmark Mode Cnt Score Error Units
ManyParametersInSetupBenchmark.fewParameters thrpt 3 5472588.826 ± 1029286.946 ops/s
```
---
[GitHub] logging-log4j2 issue #218: [LOG4J2-2475] More efficient parameter reset for ...
Posted by remkop <gi...@git.apache.org>.
Github user remkop commented on the issue:
https://github.com/apache/logging-log4j2/pull/218
That was fast, thank you Carter!
It looks to me that the difference is just a handful of nanoseconds to null out a 1000-element array.
I would expect the ringbuffer to contain mostly small arrays and an occasional large array, and only those large arrays would then take an extra few nanos to null out.
I do believe that it is more robust to null out the whole array. This allows future contributors who are perhaps less familiar with the code to make changes without breaking things.
---
[GitHub] logging-log4j2 issue #218: [LOG4J2-2475] More efficient parameter reset for ...
Posted by cakofony <gi...@git.apache.org>.
Github user cakofony commented on the issue:
https://github.com/apache/logging-log4j2/pull/218
Pushed the above idea to #220
---
[GitHub] logging-log4j2 issue #218: [LOG4J2-2475] More efficient parameter reset for ...
Posted by remkop <gi...@git.apache.org>.
Github user remkop commented on the issue:
https://github.com/apache/logging-log4j2/pull/218
I cannot imagine any program logging one million parameters so this benchmark is perhaps a bit academic. :-)
In a realistic program a "large" parameter array is probably more like 100 elements (and I would not like to maintain a program that has a logging statement with 100 parameters).
Can we measure again with an extreme case of 1000 parameters?
I suspect that with an array of 1000 (or even 10,000) elements we won't see much difference between nulling out only the first 10 or the full array, in which case it is more robust to simply null out the whole array.
---
[GitHub] logging-log4j2 issue #218: [LOG4J2-2475] More efficient parameter reset for ...
Posted by remkop <gi...@git.apache.org>.
Github user remkop commented on the issue:
https://github.com/apache/logging-log4j2/pull/218
I'm just not sure that this is a good idea.
It seems to make the code more brittle: if the code changes in the future this may break something.
It seems safer to just clear the whole array.
That said, I can be convinced otherwise if there is a clear advantage. Can you put this in perspective with some performance numbers? How much can be gained by this change?
---
[GitHub] logging-log4j2 pull request #218: [LOG4J2-2475] More efficient parameter res...
Posted by cakofony <gi...@git.apache.org>.
Github user cakofony closed the pull request at:
https://github.com/apache/logging-log4j2/pull/218
---
[GitHub] logging-log4j2 issue #218: [LOG4J2-2475] More efficient parameter reset for ...
Posted by cakofony <gi...@git.apache.org>.
Github user cakofony commented on the issue:
https://github.com/apache/logging-log4j2/pull/218
No worries, thank you for your feedback as always!
We might want to consider updating `ReusableMessageFactory.newMessage(final String message, final Object... params)` to return a non-reusable ParameterizedMessage instance. It seems like a bug that logging an object array may result in that array being mutated the next time an event is logged on the same thread. It's unfortunate that we cannot differentiate between an array passed as a value, and an array created by a varargs invocation.
Thoughts?
---