Uploaded image for project: 'Log4net'
  1. Log4net
  2. LOG4NET-429

Pattern with Context property causes severe slowdown

    Details

    • Type: Improvement
    • Status: Reopened
    • Priority: Minor
    • Resolution: Unresolved
    • Affects Version/s: 1.2.13
    • Fix Version/s: None
    • Component/s: Core
    • Labels:

      Description

      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/

      1. LOG4NET-429.patch
        8 kB
        Dominik Psenner
      2. LOG4NET-429-alternative.patch
        14 kB
        Stefan Bodewig

        Issue Links

          Activity

          Hide
          nachbarslumpi Dominik Psenner added a comment -

          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:

          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);
          		}
          	}
          }
          

          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
          <?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>
          

          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
          <?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>
          

          To me it looks like you are looking out for a performance bottleneck where there is none.

          Cheers

          Show
          nachbarslumpi Dominik Psenner added a comment - 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: 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); } } } 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 <?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> 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 <?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> To me it looks like you are looking out for a performance bottleneck where there is none. Cheers
          Hide
          nachbarslumpi Dominik Psenner added a comment -

          Cannot reproduce, therefore I'm resolving the issue. Please close it if you agree or if you don't feel free to reopen it.

          Show
          nachbarslumpi Dominik Psenner added a comment - Cannot reproduce, therefore I'm resolving the issue. Please close it if you agree or if you don't feel free to reopen it.
          Hide
          nachbarslumpi Dominik Psenner added a comment -

          Apologies. I've just run another 2 tests using a performance profiler that tracks the call stacks and it looks like your assumption is almost right. Whenever a patternlayout contains the property flag, the dictionary holding all properties is initialized as soon as the key is looked up. Therefore I've observed that the time is spent in LoggingEvent.CreatePompositeProperties(), invoked by LoggingEvent.LookupProperty(string key).

          That's the good news. The bad news is that at the moment there's no way around this because the property keys are not organized in domains. I'll have to think about how we can work around this issue.

          Show
          nachbarslumpi Dominik Psenner added a comment - Apologies. I've just run another 2 tests using a performance profiler that tracks the call stacks and it looks like your assumption is almost right. Whenever a patternlayout contains the property flag, the dictionary holding all properties is initialized as soon as the key is looked up. Therefore I've observed that the time is spent in LoggingEvent.CreatePompositeProperties(), invoked by LoggingEvent.LookupProperty(string key). That's the good news. The bad news is that at the moment there's no way around this because the property keys are not organized in domains. I'll have to think about how we can work around this issue.
          Hide
          ds99jove Jonas Versén added a comment -

          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!

          Show
          ds99jove Jonas Versén added a comment - 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!
          Hide
          nachbarslumpi Dominik Psenner added a comment -

          Thanks for the Kudos. Everyone's trying to do his best. For what its worth, I've introduced this performance bottleneck with the fix for LOG4NET-205.

          Show
          nachbarslumpi Dominik Psenner added a comment - Thanks for the Kudos. Everyone's trying to do his best. For what its worth, I've introduced this performance bottleneck with the fix for LOG4NET-205 .
          Hide
          nachbarslumpi Dominik Psenner added a comment - - edited

          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.11 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.

          Show
          nachbarslumpi Dominik Psenner added a comment - - edited 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.11 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.
          Hide
          nachbarslumpi Dominik Psenner added a comment - - edited

          This is the patch that implements solution 3, discuss.

          Show
          nachbarslumpi Dominik Psenner added a comment - - edited This is the patch that implements solution 3, discuss.
          Hide
          bodewig Stefan Bodewig added a comment - - edited

          This is LOG4NET-421 as well, right? The reporter included a workaround that may help if this becomes an issue before we fix it.

          Haven't looked at the patch, yet, but would aim for something like 3 myself.

          Show
          bodewig Stefan Bodewig added a comment - - edited This is LOG4NET-421 as well, right? The reporter included a workaround that may help if this becomes an issue before we fix it. Haven't looked at the patch, yet, but would aim for something like 3 myself.
          Hide
          nachbarslumpi Dominik Psenner added a comment -

          Indeed, I've linked and closed LOG4NET-421.

          Show
          nachbarslumpi Dominik Psenner added a comment - Indeed, I've linked and closed LOG4NET-421 .
          Hide
          nachbarslumpi Dominik Psenner added a comment -

          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.

          Show
          nachbarslumpi Dominik Psenner added a comment - 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.
          Hide
          ds99jove Jonas Versén added a comment -

          Solution 3 sounds like the best solution given the circumstances you've listed. +1 from me

          Show
          ds99jove Jonas Versén added a comment - Solution 3 sounds like the best solution given the circumstances you've listed. +1 from me
          Hide
          nachbarslumpi Dominik Psenner added a comment -

          Did someone actually test the patch against the current trunk? I would appreciate if someone did that before I commit the patch.

          Show
          nachbarslumpi Dominik Psenner added a comment - Did someone actually test the patch against the current trunk? I would appreciate if someone did that before I commit the patch.
          Hide
          bodewig Stefan Bodewig added a comment - - edited

          I like the way you've 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.

          Show
          bodewig Stefan Bodewig added a comment - - edited I like the way you've 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.
          Hide
          nachbarslumpi Dominik Psenner added a comment - - edited

          Re-reading my code now I would prefer that too. Feel free to patch the patch.

          Show
          nachbarslumpi Dominik Psenner added a comment - - edited Re-reading my code now I would prefer that too. Feel free to patch the patch.
          Hide
          bodewig Stefan Bodewig added a comment -

          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.

          Show
          bodewig Stefan Bodewig added a comment - 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.
          Hide
          bodewig Stefan Bodewig added a comment -

          This is an alternative patch which has arguably not been tested much.

          Flatten is probably only called on CompositeProperties in situations where you really want to "fix" the UserName as well.

          Show
          bodewig Stefan Bodewig added a comment - This is an alternative patch which has arguably not been tested much. Flatten is probably only called on CompositeProperties in situations where you really want to "fix" the UserName as well.
          Hide
          nachbarslumpi Dominik Psenner added a comment -

          As far as I can recall, every composite dictionary was flattened at some point when I wrote my patch.

          Show
          nachbarslumpi Dominik Psenner added a comment - As far as I can recall, every composite dictionary was flattened at some point when I wrote my patch.
          Hide
          bodewig Stefan Bodewig added a comment -

          Hmm. in that case any patch that tried to generalize laziness would become pretty convoluted. Let's stick with your original patch.

          Show
          bodewig Stefan Bodewig added a comment - Hmm. in that case any patch that tried to generalize laziness would become pretty convoluted. Let's stick with your original patch.
          Hide
          nachbarslumpi Dominik Psenner added a comment -

          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?

          Show
          nachbarslumpi Dominik Psenner added a comment - 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?
          Hide
          githubbot ASF GitHub Bot added a comment -

          Github user dpsenner commented on the issue:

          https://github.com/apache/logging-log4net/pull/5

          There is an issue for this too (LOG4NET-429).

          Show
          githubbot ASF GitHub Bot added a comment - Github user dpsenner commented on the issue: https://github.com/apache/logging-log4net/pull/5 There is an issue for this too ( LOG4NET-429 ).
          Hide
          githubbot ASF GitHub Bot added a comment -

          Github user dpsenner commented on the issue:

          https://github.com/apache/logging-log4net/pull/5

          The patches available as attachments on issue LOG4NET-429 look more sensible to me. This patch simply removes this feature and thus breaks current behavior. In my eyes this is not a great deal.

          Show
          githubbot ASF GitHub Bot added a comment - Github user dpsenner commented on the issue: https://github.com/apache/logging-log4net/pull/5 The patches available as attachments on issue LOG4NET-429 look more sensible to me. This patch simply removes this feature and thus breaks current behavior. In my eyes this is not a great deal.

            People

            • Assignee:
              nachbarslumpi Dominik Psenner
              Reporter:
              ds99jove Jonas Versén
            • Votes:
              2 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

              • Created:
                Updated:

                Development