[jira] [Commented] (LOG4NET-429) Pattern with Context property causes severe slowdown
[ https://issues.apache.org/jira/browse/LOG4NET-429?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=14018574#comment-14018574 ] Dominik Psenner commented on LOG4NET-429: - Your patch makes sense, but flattening a dictionary may no longer produce a flattened dictionary. Thus, there be dragons. And after all I might be wrong - my memory is not one of the best. :-) What if you used the debugger to step through and check whether your patch works against the code above? Pattern with Context property causes severe slowdown Key: LOG4NET-429 URL: https://issues.apache.org/jira/browse/LOG4NET-429 Project: Log4net Issue Type: Improvement Components: Core Affects Versions: 1.2.13 Reporter: Jonas Versén Assignee: Dominik Psenner Priority: Minor Labels: performance Attachments: LOG4NET-429-alternative.patch, LOG4NET-429.patch If you use a context property in your appenders pattern, there will be a significant logging slowdown. In my experience anywhere from 3 to 5 times slower (this will depend on the appender). I believe that as soon as you use a context property log4net will internally access the windows user name even though it's not the property you want to access. This theory comes from the fact that printing all properties in the pattern (including the costly property username) compared to just printing one will slow down the logging with the same factor. I've made a stackoverflow question with more details as well http://stackoverflow.com/questions/22612286/using-log4net-context-properties-has-negative-impact-on-performance/ -- This message was sent by Atlassian JIRA (v6.2#6252)
[jira] [Commented] (LOG4NET-429) Pattern with Context property causes severe slowdown
[ https://issues.apache.org/jira/browse/LOG4NET-429?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=14017739#comment-14017739 ] Dominik Psenner commented on LOG4NET-429: - As far as I can recall, every composite dictionary was flattened at some point when I wrote my patch. Pattern with Context property causes severe slowdown Key: LOG4NET-429 URL: https://issues.apache.org/jira/browse/LOG4NET-429 Project: Log4net Issue Type: Improvement Components: Core Affects Versions: 1.2.13 Reporter: Jonas Versén Assignee: Dominik Psenner Priority: Minor Labels: performance Attachments: LOG4NET-429-alternative.patch, LOG4NET-429.patch If you use a context property in your appenders pattern, there will be a significant logging slowdown. In my experience anywhere from 3 to 5 times slower (this will depend on the appender). I believe that as soon as you use a context property log4net will internally access the windows user name even though it's not the property you want to access. This theory comes from the fact that printing all properties in the pattern (including the costly property username) compared to just printing one will slow down the logging with the same factor. I've made a stackoverflow question with more details as well http://stackoverflow.com/questions/22612286/using-log4net-context-properties-has-negative-impact-on-performance/ -- This message was sent by Atlassian JIRA (v6.2#6252)
[jira] [Commented] (LOG4NET-429) Pattern with Context property causes severe slowdown
[ https://issues.apache.org/jira/browse/LOG4NET-429?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=14017765#comment-14017765 ] Stefan Bodewig commented on LOG4NET-429: Hmm. in that case any patch that tried to generalize laziness would become pretty convoluted. Let's stick with your original patch. Pattern with Context property causes severe slowdown Key: LOG4NET-429 URL: https://issues.apache.org/jira/browse/LOG4NET-429 Project: Log4net Issue Type: Improvement Components: Core Affects Versions: 1.2.13 Reporter: Jonas Versén Assignee: Dominik Psenner Priority: Minor Labels: performance Attachments: LOG4NET-429-alternative.patch, LOG4NET-429.patch If you use a context property in your appenders pattern, there will be a significant logging slowdown. In my experience anywhere from 3 to 5 times slower (this will depend on the appender). I believe that as soon as you use a context property log4net will internally access the windows user name even though it's not the property you want to access. This theory comes from the fact that printing all properties in the pattern (including the costly property username) compared to just printing one will slow down the logging with the same factor. I've made a stackoverflow question with more details as well http://stackoverflow.com/questions/22612286/using-log4net-context-properties-has-negative-impact-on-performance/ -- This message was sent by Atlassian JIRA (v6.2#6252)
[jira] [Commented] (LOG4NET-429) Pattern with Context property causes severe slowdown
[ https://issues.apache.org/jira/browse/LOG4NET-429?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=14016878#comment-14016878 ] Dominik Psenner commented on LOG4NET-429: - I would prefer that too. Feel free to patch the patch. :-) Pattern with Context property causes severe slowdown Key: LOG4NET-429 URL: https://issues.apache.org/jira/browse/LOG4NET-429 Project: Log4net Issue Type: Improvement Components: Core Affects Versions: 1.2.13 Reporter: Jonas Versén Assignee: Dominik Psenner Priority: Minor Labels: performance Attachments: LOG4NET-429.patch If you use a context property in your appenders pattern, there will be a significant logging slowdown. In my experience anywhere from 3 to 5 times slower (this will depend on the appender). I believe that as soon as you use a context property log4net will internally access the windows user name even though it's not the property you want to access. This theory comes from the fact that printing all properties in the pattern (including the costly property username) compared to just printing one will slow down the logging with the same factor. I've made a stackoverflow question with more details as well http://stackoverflow.com/questions/22612286/using-log4net-context-properties-has-negative-impact-on-performance/ -- This message was sent by Atlassian JIRA (v6.2#6252)
[jira] [Commented] (LOG4NET-429) Pattern with Context property causes severe slowdown
[ https://issues.apache.org/jira/browse/LOG4NET-429?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=14017010#comment-14017010 ] Stefan Bodewig commented on LOG4NET-429: CompositeProperties.Flatten is going to byte us this way, as it would remove all lazyness. It seems as if it wouldn't be possible to achieve lazy evaluation without modifying CompositeProperties one way or another. I'll play with it a little. Pattern with Context property causes severe slowdown Key: LOG4NET-429 URL: https://issues.apache.org/jira/browse/LOG4NET-429 Project: Log4net Issue Type: Improvement Components: Core Affects Versions: 1.2.13 Reporter: Jonas Versén Assignee: Dominik Psenner Priority: Minor Labels: performance Attachments: LOG4NET-429.patch If you use a context property in your appenders pattern, there will be a significant logging slowdown. In my experience anywhere from 3 to 5 times slower (this will depend on the appender). I believe that as soon as you use a context property log4net will internally access the windows user name even though it's not the property you want to access. This theory comes from the fact that printing all properties in the pattern (including the costly property username) compared to just printing one will slow down the logging with the same factor. I've made a stackoverflow question with more details as well http://stackoverflow.com/questions/22612286/using-log4net-context-properties-has-negative-impact-on-performance/ -- This message was sent by Atlassian JIRA (v6.2#6252)
[jira] [Commented] (LOG4NET-429) Pattern with Context property causes severe slowdown
[ https://issues.apache.org/jira/browse/LOG4NET-429?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=14015049#comment-14015049 ] Stefan Bodewig commented on LOG4NET-429: I like the way you've moved lifted the code to SystemInfo Personally I would probably add a new ReadOnlyPropertiesDictionary with the lazy loading semantics and add that to the m_compositeProperties instance rather than add the caching inside ComositeProperties but I haven't got any working code to show right now and your solution works just as well. Pattern with Context property causes severe slowdown Key: LOG4NET-429 URL: https://issues.apache.org/jira/browse/LOG4NET-429 Project: Log4net Issue Type: Improvement Components: Core Affects Versions: 1.2.13 Reporter: Jonas Versén Assignee: Dominik Psenner Priority: Minor Labels: performance Attachments: LOG4NET-429.patch If you use a context property in your appenders pattern, there will be a significant logging slowdown. In my experience anywhere from 3 to 5 times slower (this will depend on the appender). I believe that as soon as you use a context property log4net will internally access the windows user name even though it's not the property you want to access. This theory comes from the fact that printing all properties in the pattern (including the costly property username) compared to just printing one will slow down the logging with the same factor. I've made a stackoverflow question with more details as well http://stackoverflow.com/questions/22612286/using-log4net-context-properties-has-negative-impact-on-performance/ -- This message was sent by Atlassian JIRA (v6.2#6252)
[jira] [Commented] (LOG4NET-429) Pattern with Context property causes severe slowdown
[ https://issues.apache.org/jira/browse/LOG4NET-429?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13947735#comment-13947735 ] Jonas Versén commented on LOG4NET-429: -- Solution 3 sounds like the best solution given the circumstances you've listed. +1 from me Pattern with Context property causes severe slowdown Key: LOG4NET-429 URL: https://issues.apache.org/jira/browse/LOG4NET-429 Project: Log4net Issue Type: Improvement Components: Core Affects Versions: 1.2.13 Reporter: Jonas Versén Assignee: Dominik Psenner Priority: Minor Labels: performance Attachments: LOG4NET-429.patch If you use a context property in your appenders pattern, there will be a significant logging slowdown. In my experience anywhere from 3 to 5 times slower (this will depend on the appender). I believe that as soon as you use a context property log4net will internally access the windows user name even though it's not the property you want to access. This theory comes from the fact that printing all properties in the pattern (including the costly property username) compared to just printing one will slow down the logging with the same factor. I've made a stackoverflow question with more details as well http://stackoverflow.com/questions/22612286/using-log4net-context-properties-has-negative-impact-on-performance/ -- This message was sent by Atlassian JIRA (v6.2#6252)
[jira] [Commented] (LOG4NET-429) Pattern with Context property causes severe slowdown
[ https://issues.apache.org/jira/browse/LOG4NET-429?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13947840#comment-13947840 ] Dominik Psenner commented on LOG4NET-429: - Did someone actually test the patch against the current trunk? I would appreciate if someone did that before I commit the patch. Pattern with Context property causes severe slowdown Key: LOG4NET-429 URL: https://issues.apache.org/jira/browse/LOG4NET-429 Project: Log4net Issue Type: Improvement Components: Core Affects Versions: 1.2.13 Reporter: Jonas Versén Assignee: Dominik Psenner Priority: Minor Labels: performance Attachments: LOG4NET-429.patch If you use a context property in your appenders pattern, there will be a significant logging slowdown. In my experience anywhere from 3 to 5 times slower (this will depend on the appender). I believe that as soon as you use a context property log4net will internally access the windows user name even though it's not the property you want to access. This theory comes from the fact that printing all properties in the pattern (including the costly property username) compared to just printing one will slow down the logging with the same factor. I've made a stackoverflow question with more details as well http://stackoverflow.com/questions/22612286/using-log4net-context-properties-has-negative-impact-on-performance/ -- This message was sent by Atlassian JIRA (v6.2#6252)
[jira] [Commented] (LOG4NET-429) Pattern with Context property causes severe slowdown
[
https://issues.apache.org/jira/browse/LOG4NET-429?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13946297#comment-13946297
]
Dominik Psenner commented on LOG4NET-429:
-
Hi there.
I modified your sample slightly to do 100 runs, each run logging 1000 times to
both appenders. The test code run is the following:
{code}
using log4net;
using System;
using System.Collections;
using System.Collections.Generic;
using System.Diagnostics;
using System.Linq;
using System.Text;
using System.Threading.Tasks;
namespace ConsoleApplication1
{
class Program
{
static void Main(string[] args)
{
// Arrange
log4net.Config.XmlConfigurator.Configure();
GlobalContext.Properties[customProperty] = Test;
var nrOfRepetitions = 1000;
var noPropertyLogger =
LogManager.GetLogger(NoProperty);
var propertyLogger =
LogManager.GetLogger(HasProperty);
var noPropertyStopwatch = new Stopwatch();
var propertyStopwatch = new Stopwatch();
Listlong noPropertyTimesGlob = new Listlong();
Listlong propertyTimesGlob = new Listlong();
int totalRuns = 100;
for (int run = 0; run totalRuns; run++)
{
Console.WriteLine(Run #{0}, run);
noPropertyStopwatch.Reset();
noPropertyStopwatch.Start();
for (int i = 0; i nrOfRepetitions; i++)
{
noPropertyLogger.Info(Logging without
custom Parameter.);
}
noPropertyStopwatch.Stop();
noPropertyTimesGlob.Add(noPropertyStopwatch.ElapsedMilliseconds);
propertyStopwatch.Reset();
propertyStopwatch.Start();
for (int i = 0; i nrOfRepetitions; i++)
{
propertyLogger.Info(Logging with
custom parameter);
}
propertyStopwatch.Stop();
propertyTimesGlob.Add(propertyStopwatch.ElapsedMilliseconds);
Console.WriteLine( - Elapsed time: (No
property) {0}, noPropertyTimesGlob.Last());
Console.WriteLine( - Elapsed time: (With
property) {0}, propertyTimesGlob.Last());
}
Console.WriteLine(Total {0} runs, each run {1}
repetitions:, totalRuns, nrOfRepetitions);
Console.WriteLine( - Elapsed time: (No property)
min={0}, max={1}, avg={2}, stdev={3}, noPropertyTimesGlob.Min(),
noPropertyTimesGlob.Max(), noPropertyTimesGlob.Average(),
noPropertyTimesGlob.StdDev());
Console.WriteLine( - Elapsed time: (With property)
min={0}, max={1}, avg={2}, stdev={3}, propertyTimesGlob.Min(),
propertyTimesGlob.Max(), propertyTimesGlob.Average(),
propertyTimesGlob.StdDev());
Console.ReadLine();
}
}
public static class Extensions
{
public static double StdDev(this Listlong values)
{
double avg = values.Average();
double sum = values.Sum(d = Math.Pow(d - avg, 2));
return Math.Sqrt(sum / values.Count);
}
}
}
{code}
Using the configuration below, the results were:
Total 100 runs, each run 1000 repetitions:
- Elapsed time: (No property) min=282, max=465, avg=311,42,
stdev=26,0768786475682
- Elapsed time: (With property) min=282, max=557, avg=313,62,
stdev=34,007465297
{code}
?xml version=1.0 encoding=utf-8 ?
configuration
configSections
section name=log4net
type=log4net.Config.Log4NetConfigurationSectionHandler, log4net /
/configSections
log4net
appender name=NoPropertyAppender type=log4net.Appender.MemoryAppender
layout type=log4net.Layout.PatternLayout
conversionPattern value=%message%newline /
/layout
/appender
appender name=PropertyAppender type=log4net.Appender.MemoryAppender
layout type=log4net.Layout.PatternLayout
conversionPattern value=%property{customProperty}- %message%newline
/
/layout
/appender
logger name=NoProperty
level value=DEBUG /
appender-ref ref=NoPropertyAppender /
/logger
logger name=HasProperty
level value=DEBUG /
appender-ref ref=PropertyAppender /
/logger
[jira] [Commented] (LOG4NET-429) Pattern with Context property causes severe slowdown
[ https://issues.apache.org/jira/browse/LOG4NET-429?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13946430#comment-13946430 ] Jonas Versén commented on LOG4NET-429: -- I'm happy that you found the bug! It's not a performance bottleneck for us atm and as long as it's a known issue and its in the roadmap, I'm content. Thank you for the quick response btw! Pattern with Context property causes severe slowdown Key: LOG4NET-429 URL: https://issues.apache.org/jira/browse/LOG4NET-429 Project: Log4net Issue Type: Improvement Components: Core Affects Versions: 1.2.13 Reporter: Jonas Versén Assignee: Dominik Psenner Priority: Minor Labels: performance If you use a context property in your appenders pattern, there will be a significant logging slowdown. In my experience anywhere from 3 to 5 times slower (this will depend on the appender). I believe that as soon as you use a context property log4net will internally access the windows user name even though it's not the property you want to access. This theory comes from the fact that printing all properties in the pattern (including the costly property username) compared to just printing one will slow down the logging with the same factor. I've made a stackoverflow question with more details as well http://stackoverflow.com/questions/22612286/using-log4net-context-properties-has-negative-impact-on-performance/ -- This message was sent by Atlassian JIRA (v6.2#6252)
[jira] [Commented] (LOG4NET-429) Pattern with Context property causes severe slowdown
[
https://issues.apache.org/jira/browse/LOG4NET-429?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13946453#comment-13946453
]
Dominik Psenner commented on LOG4NET-429:
-
So far I came up with 3 solutions and let's discuss about those:
1] revert LOG4NET-205 and add a UserNameFilter and a IdentityFilter instead
2] add a global configuration flag that allows log4net to decide whether it
should populate the UserName and the Identity into the event properties
dictionary
3] hack the properties dictionary to treat the UserNameProperty and the
IdentityProperty specially, allowing them to be looked up and cached only when
they are requested
With 1 we solve the issue for good but we also drop a feature that has been
introduced with 1.2.13 and thus we break backwards compatibilty. With 2 we
allow people to work around the issue when they are concerned about performance
but do not solve the issue for real. 3 will be the solution with no impact on
the public API, but introduces a dirty hack.
From my point of view we should aim towards solution 3 and thus I'm attaching
a working patch that suffers from the performance penalty only if somebody
effectively uses _%property\{log4net:UserName}_ in the pattern layout.
Pattern with Context property causes severe slowdown
Key: LOG4NET-429
URL: https://issues.apache.org/jira/browse/LOG4NET-429
Project: Log4net
Issue Type: Improvement
Components: Core
Affects Versions: 1.2.13
Reporter: Jonas Versén
Assignee: Dominik Psenner
Priority: Minor
Labels: performance
If you use a context property in your appenders pattern, there will be a
significant logging slowdown. In my experience anywhere from 3 to 5 times
slower (this will depend on the appender).
I believe that as soon as you use a context property log4net will internally
access the windows user name even though it's not the property you want to
access. This theory comes from the fact that printing all properties in the
pattern (including the costly property username) compared to just printing
one will slow down the logging with the same factor.
I've made a stackoverflow question with more details as well
http://stackoverflow.com/questions/22612286/using-log4net-context-properties-has-negative-impact-on-performance/
--
This message was sent by Atlassian JIRA
(v6.2#6252)
[jira] [Commented] (LOG4NET-429) Pattern with Context property causes severe slowdown
[ https://issues.apache.org/jira/browse/LOG4NET-429?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13946483#comment-13946483 ] Stefan Bodewig commented on LOG4NET-429: This is LOG4NET-421 as well, right? Haven't looked at the patch, yet, but would aim for something like 3 myself. Pattern with Context property causes severe slowdown Key: LOG4NET-429 URL: https://issues.apache.org/jira/browse/LOG4NET-429 Project: Log4net Issue Type: Improvement Components: Core Affects Versions: 1.2.13 Reporter: Jonas Versén Assignee: Dominik Psenner Priority: Minor Labels: performance Attachments: LOG4NET-429.patch If you use a context property in your appenders pattern, there will be a significant logging slowdown. In my experience anywhere from 3 to 5 times slower (this will depend on the appender). I believe that as soon as you use a context property log4net will internally access the windows user name even though it's not the property you want to access. This theory comes from the fact that printing all properties in the pattern (including the costly property username) compared to just printing one will slow down the logging with the same factor. I've made a stackoverflow question with more details as well http://stackoverflow.com/questions/22612286/using-log4net-context-properties-has-negative-impact-on-performance/ -- This message was sent by Atlassian JIRA (v6.2#6252)
[jira] [Commented] (LOG4NET-429) Pattern with Context property causes severe slowdown
[
https://issues.apache.org/jira/browse/LOG4NET-429?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13946509#comment-13946509
]
Dominik Psenner commented on LOG4NET-429:
-
Alright, with another +1 for solution 3 I'll commit the patch. So far I've
tested the functionality and ran performance tests, meaning that the username
appears in the rendered log messages and the performance penalty is hit only in
those cases where the username is rendered. However, the performance hit is
still doubled when one uses a combination of _%username_ and
_%properties\{log4net:UserName}_ in one pattern but unfortunately there's no
easy way around that. I'm considering that as a bearable compromise.
Pattern with Context property causes severe slowdown
Key: LOG4NET-429
URL: https://issues.apache.org/jira/browse/LOG4NET-429
Project: Log4net
Issue Type: Improvement
Components: Core
Affects Versions: 1.2.13
Reporter: Jonas Versén
Assignee: Dominik Psenner
Priority: Minor
Labels: performance
Attachments: LOG4NET-429.patch
If you use a context property in your appenders pattern, there will be a
significant logging slowdown. In my experience anywhere from 3 to 5 times
slower (this will depend on the appender).
I believe that as soon as you use a context property log4net will internally
access the windows user name even though it's not the property you want to
access. This theory comes from the fact that printing all properties in the
pattern (including the costly property username) compared to just printing
one will slow down the logging with the same factor.
I've made a stackoverflow question with more details as well
http://stackoverflow.com/questions/22612286/using-log4net-context-properties-has-negative-impact-on-performance/
--
This message was sent by Atlassian JIRA
(v6.2#6252)
