You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by Gary Gregory <ga...@gmail.com> on 2015/07/09 01:20:21 UTC
Empty Filters in config has performance implication
Hi All:
I am now profiling my JDBC driver and I was surprised to see Log4j's
CompositeFilter.filter() show up at 0.9% of CPU time when I had logging set
to INFO which only logged two events for the whole test run. The driver
does a lot of flow tracing at the TRACE level so Log4j gets called _a lot_.
In my XML config, I have a Filters element with a bunch of Filter child
elements.When I am debugging, I comment some filters in and out. Most of
the time, I am not debugging, so I have all the individual filters
commented out. The top level Filters element is still there.
If I completely remove all filters from the config (no Filters element),
then the CompositeFilter disappears from profiling.
Now that I've looked at the code, I see that the behavior is explained by:
@PluginFactory
public static CompositeFilter createFilters(@PluginElement("Filters")
final Filter[] filters) {
final List<Filter> filterList = filters == null || filters.length
== 0 ?
new ArrayList<Filter>() : Arrays.asList(filters);
return new CompositeFilter(filterList);
}
An XML fragment like <Filters></Filters> always creates a CompositeFilter
even though there is nothing to filter.
I'm not sure what is the best way to fix this. The CompositeFilter could
accept a null and treat it specially (not pretty or effective since
filter() still gets called a gazillion times). Ideally, the createFilters
should not even be called in the empty Filters element case.
This is too nasty and obscure to put in the FAQ so I'd like to discuss how
to fix it.
Thoughts?
Thank you,
Gary
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
Java Persistence with Hibernate, Second Edition
<http://www.manning.com/bauer3/>
JUnit in Action, Second Edition <http://www.manning.com/tahchiev/>
Spring Batch in Action <http://www.manning.com/templier/>
Blog: http://garygregory.wordpress.com
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
Re: Empty Filters in config has performance implication
Posted by Mikael Ståldal <mi...@magine.com>.
You might be able to optimize this a bit by replacing
new ArrayList<Filter>()
with
Collections.emptyList()
On Thu, Jul 9, 2015 at 1:20 AM, Gary Gregory <ga...@gmail.com> wrote:
> Hi All:
>
> I am now profiling my JDBC driver and I was surprised to see Log4j's
> CompositeFilter.filter() show up at 0.9% of CPU time when I had logging set
> to INFO which only logged two events for the whole test run. The driver
> does a lot of flow tracing at the TRACE level so Log4j gets called _a lot_.
>
> In my XML config, I have a Filters element with a bunch of Filter child
> elements.When I am debugging, I comment some filters in and out. Most of
> the time, I am not debugging, so I have all the individual filters
> commented out. The top level Filters element is still there.
>
> If I completely remove all filters from the config (no Filters element),
> then the CompositeFilter disappears from profiling.
>
> Now that I've looked at the code, I see that the behavior is explained by:
>
> @PluginFactory
> public static CompositeFilter createFilters(@PluginElement("Filters")
> final Filter[] filters) {
> final List<Filter> filterList = filters == null || filters.length
> == 0 ?
> new ArrayList<Filter>() : Arrays.asList(filters);
> return new CompositeFilter(filterList);
> }
>
> An XML fragment like <Filters></Filters> always creates a CompositeFilter
> even though there is nothing to filter.
>
> I'm not sure what is the best way to fix this. The CompositeFilter could
> accept a null and treat it specially (not pretty or effective since
> filter() still gets called a gazillion times). Ideally, the createFilters
> should not even be called in the empty Filters element case.
>
> This is too nasty and obscure to put in the FAQ so I'd like to discuss how
> to fix it.
>
> Thoughts?
>
> Thank you,
> Gary
>
> --
> E-Mail: garydgregory@gmail.com | ggregory@apache.org
> Java Persistence with Hibernate, Second Edition
> <http://www.manning.com/bauer3/>
> JUnit in Action, Second Edition <http://www.manning.com/tahchiev/>
> Spring Batch in Action <http://www.manning.com/templier/>
> Blog: http://garygregory.wordpress.com
> Home: http://garygregory.com/
> Tweet! http://twitter.com/GaryGregory
>
--
[image: MagineTV]
*Mikael Ståldal*
Senior backend developer
*Magine TV*
mikael.staldal@magine.com
Regeringsgatan 25 | 111 53 Stockholm, Sweden | www.magine.com
Privileged and/or Confidential Information may be contained in this
message. If you are not the addressee indicated in this message
(or responsible for delivery of the message to such a person), you may not
copy or deliver this message to anyone. In such case,
you should destroy this message and kindly notify the sender by reply
email.
Re: Empty Filters in config has performance implication
Posted by Gary Gregory <ga...@gmail.com>.
It does not make sense I agree. I tried again and it does not show up. I
think I must have not had the updated config file deployed to the remote VM
I used for testing... sorry about the noise.
The Log4j hot spot that does show up in my current config is
AbstractLogger.isTraceEnabled() for 2.3% of CPU. I do not quite see how to
make the meat of that faster.
I wonder how much time would be saved if the config file check is migrated
to a Java 7 file watcher? I do have the refresh check set to the min value
of 5 seconds.
Gary
On Wed, Jul 8, 2015 at 9:13 PM, Ralph Goers <ra...@dslextreme.com>
wrote:
> How can CompositeFilter.filter() show up as a hot spot if you don’t have
> any filters at all?
>
> Ralph
>
> On Jul 8, 2015, at 4:26 PM, Gary Gregory <ga...@gmail.com> wrote:
>
> More data, it must have been a fluke because CompositeFilter.filter()
> still shows up high in the hot spot list of methods called. I do not have
> any Filter XML in my config...
>
> Gary
>
> On Wed, Jul 8, 2015 at 4:20 PM, Gary Gregory <ga...@gmail.com>
> wrote:
>
>> Hi All:
>>
>> I am now profiling my JDBC driver and I was surprised to see Log4j's
>> CompositeFilter.filter() show up at 0.9% of CPU time when I had logging set
>> to INFO which only logged two events for the whole test run. The driver
>> does a lot of flow tracing at the TRACE level so Log4j gets called _a lot_.
>>
>> In my XML config, I have a Filters element with a bunch of Filter child
>> elements.When I am debugging, I comment some filters in and out. Most of
>> the time, I am not debugging, so I have all the individual filters
>> commented out. The top level Filters element is still there.
>>
>> If I completely remove all filters from the config (no Filters element),
>> then the CompositeFilter disappears from profiling.
>>
>> Now that I've looked at the code, I see that the behavior is explained by:
>>
>> @PluginFactory
>> public static CompositeFilter createFilters(@PluginElement("Filters")
>> final Filter[] filters) {
>> final List<Filter> filterList = filters == null || filters.length
>> == 0 ?
>> new ArrayList<Filter>() : Arrays.asList(filters);
>> return new CompositeFilter(filterList);
>> }
>>
>> An XML fragment like <Filters></Filters> always creates a CompositeFilter
>> even though there is nothing to filter.
>>
>> I'm not sure what is the best way to fix this. The CompositeFilter could
>> accept a null and treat it specially (not pretty or effective since
>> filter() still gets called a gazillion times). Ideally, the createFilters
>> should not even be called in the empty Filters element case.
>>
>> This is too nasty and obscure to put in the FAQ so I'd like to discuss
>> how to fix it.
>>
>> Thoughts?
>>
>> Thank you,
>> Gary
>>
>> --
>> E-Mail: garydgregory@gmail.com | ggregory@apache.org
>> Java Persistence with Hibernate, Second Edition
>> <http://www.manning.com/bauer3/>
>> JUnit in Action, Second Edition <http://www.manning.com/tahchiev/>
>> Spring Batch in Action <http://www.manning.com/templier/>
>> Blog: http://garygregory.wordpress.com
>> Home: http://garygregory.com/
>> Tweet! http://twitter.com/GaryGregory
>>
>
>
>
> --
> E-Mail: garydgregory@gmail.com | ggregory@apache.org
> Java Persistence with Hibernate, Second Edition
> <http://www.manning.com/bauer3/>
> JUnit in Action, Second Edition <http://www.manning.com/tahchiev/>
> Spring Batch in Action <http://www.manning.com/templier/>
> Blog: http://garygregory.wordpress.com
> Home: http://garygregory.com/
> Tweet! http://twitter.com/GaryGregory
>
>
>
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
Java Persistence with Hibernate, Second Edition
<http://www.manning.com/bauer3/>
JUnit in Action, Second Edition <http://www.manning.com/tahchiev/>
Spring Batch in Action <http://www.manning.com/templier/>
Blog: http://garygregory.wordpress.com
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory
Re: Empty Filters in config has performance implication
Posted by Ralph Goers <ra...@dslextreme.com>.
How can CompositeFilter.filter() show up as a hot spot if you don’t have any filters at all?
Ralph
> On Jul 8, 2015, at 4:26 PM, Gary Gregory <ga...@gmail.com> wrote:
>
> More data, it must have been a fluke because CompositeFilter.filter() still shows up high in the hot spot list of methods called. I do not have any Filter XML in my config...
>
> Gary
>
> On Wed, Jul 8, 2015 at 4:20 PM, Gary Gregory <garydgregory@gmail.com <ma...@gmail.com>> wrote:
> Hi All:
>
> I am now profiling my JDBC driver and I was surprised to see Log4j's CompositeFilter.filter() show up at 0.9% of CPU time when I had logging set to INFO which only logged two events for the whole test run. The driver does a lot of flow tracing at the TRACE level so Log4j gets called _a lot_.
>
> In my XML config, I have a Filters element with a bunch of Filter child elements.When I am debugging, I comment some filters in and out. Most of the time, I am not debugging, so I have all the individual filters commented out. The top level Filters element is still there.
>
> If I completely remove all filters from the config (no Filters element), then the CompositeFilter disappears from profiling.
>
> Now that I've looked at the code, I see that the behavior is explained by:
>
> @PluginFactory
> public static CompositeFilter createFilters(@PluginElement("Filters") final Filter[] filters) {
> final List<Filter> filterList = filters == null || filters.length == 0 ?
> new ArrayList<Filter>() : Arrays.asList(filters);
> return new CompositeFilter(filterList);
> }
>
> An XML fragment like <Filters></Filters> always creates a CompositeFilter even though there is nothing to filter.
>
> I'm not sure what is the best way to fix this. The CompositeFilter could accept a null and treat it specially (not pretty or effective since filter() still gets called a gazillion times). Ideally, the createFilters should not even be called in the empty Filters element case.
>
> This is too nasty and obscure to put in the FAQ so I'd like to discuss how to fix it.
>
> Thoughts?
>
> Thank you,
> Gary
>
> --
> E-Mail: garydgregory@gmail.com <ma...@gmail.com> | ggregory@apache.org <ma...@apache.org>
> Java Persistence with Hibernate, Second Edition <http://www.manning.com/bauer3/>
> JUnit in Action, Second Edition <http://www.manning.com/tahchiev/>
> Spring Batch in Action <http://www.manning.com/templier/>
> Blog: http://garygregory.wordpress.com <http://garygregory.wordpress.com/>
> Home: http://garygregory.com/ <http://garygregory.com/>
> Tweet! http://twitter.com/GaryGregory <http://twitter.com/GaryGregory>
>
>
> --
> E-Mail: garydgregory@gmail.com <ma...@gmail.com> | ggregory@apache.org <ma...@apache.org>
> Java Persistence with Hibernate, Second Edition <http://www.manning.com/bauer3/>
> JUnit in Action, Second Edition <http://www.manning.com/tahchiev/>
> Spring Batch in Action <http://www.manning.com/templier/>
> Blog: http://garygregory.wordpress.com <http://garygregory.wordpress.com/>
> Home: http://garygregory.com/ <http://garygregory.com/>
> Tweet! http://twitter.com/GaryGregory <http://twitter.com/GaryGregory>
Re: Empty Filters in config has performance implication
Posted by Gary Gregory <ga...@gmail.com>.
More data, it must have been a fluke because CompositeFilter.filter() still
shows up high in the hot spot list of methods called. I do not have any
Filter XML in my config...
Gary
On Wed, Jul 8, 2015 at 4:20 PM, Gary Gregory <ga...@gmail.com> wrote:
> Hi All:
>
> I am now profiling my JDBC driver and I was surprised to see Log4j's
> CompositeFilter.filter() show up at 0.9% of CPU time when I had logging set
> to INFO which only logged two events for the whole test run. The driver
> does a lot of flow tracing at the TRACE level so Log4j gets called _a lot_.
>
> In my XML config, I have a Filters element with a bunch of Filter child
> elements.When I am debugging, I comment some filters in and out. Most of
> the time, I am not debugging, so I have all the individual filters
> commented out. The top level Filters element is still there.
>
> If I completely remove all filters from the config (no Filters element),
> then the CompositeFilter disappears from profiling.
>
> Now that I've looked at the code, I see that the behavior is explained by:
>
> @PluginFactory
> public static CompositeFilter createFilters(@PluginElement("Filters")
> final Filter[] filters) {
> final List<Filter> filterList = filters == null || filters.length
> == 0 ?
> new ArrayList<Filter>() : Arrays.asList(filters);
> return new CompositeFilter(filterList);
> }
>
> An XML fragment like <Filters></Filters> always creates a CompositeFilter
> even though there is nothing to filter.
>
> I'm not sure what is the best way to fix this. The CompositeFilter could
> accept a null and treat it specially (not pretty or effective since
> filter() still gets called a gazillion times). Ideally, the createFilters
> should not even be called in the empty Filters element case.
>
> This is too nasty and obscure to put in the FAQ so I'd like to discuss how
> to fix it.
>
> Thoughts?
>
> Thank you,
> Gary
>
> --
> E-Mail: garydgregory@gmail.com | ggregory@apache.org
> Java Persistence with Hibernate, Second Edition
> <http://www.manning.com/bauer3/>
> JUnit in Action, Second Edition <http://www.manning.com/tahchiev/>
> Spring Batch in Action <http://www.manning.com/templier/>
> Blog: http://garygregory.wordpress.com
> Home: http://garygregory.com/
> Tweet! http://twitter.com/GaryGregory
>
--
E-Mail: garydgregory@gmail.com | ggregory@apache.org
Java Persistence with Hibernate, Second Edition
<http://www.manning.com/bauer3/>
JUnit in Action, Second Edition <http://www.manning.com/tahchiev/>
Spring Batch in Action <http://www.manning.com/templier/>
Blog: http://garygregory.wordpress.com
Home: http://garygregory.com/
Tweet! http://twitter.com/GaryGregory