logging-log4net-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Dominik Psenner (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (LOG4NET-429) Pattern with Context property causes severe slowdown
Date Tue, 25 Mar 2014 08:44:42 GMT

    [ 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)

Mime
View raw message