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