[
https://issues.apache.org/jira/browse/LOG4NET-429?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=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();
List<long> noPropertyTimesGlob = new List<long>();
List<long> propertyTimesGlob = new List<long>();
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 List<long> 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,0011117465297
{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>
</log4net>
<startup>
<supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.5" />
</startup>
</configuration>
{code}
Using the configuration below, the results were:
Total 100 runs, each run 1000 repetitions:
- Elapsed time: (No property) min=44, max=197, avg=54,05,
stdev=14,8643028763545
- Elapsed time: (With property) min=145, max=183, avg=166,
stdev=9,55719624157629
{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.ConsoleAppender">
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value="%message%newline" />
</layout>
</appender>
<appender name="PropertyAppender" type="log4net.Appender.ConsoleAppender">
<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>
</log4net>
<startup>
<supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.5" />
</startup>
</configuration>
{code}
To me it looks like you are looking out for a performance bottleneck where
there is none.
Cheers
> 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: Appenders
> Affects Versions: 1.2.13
> Reporter: Jonas Versén
> Priority: Minor
>
> 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)
