Log4net
  1. Log4net
  2. LOG4NET-290

Add Lambda-based ILog-Extensions (embedded log.IsEnabled)

    Details

    • Type: New Feature New Feature
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 1.2.10
    • Fix Version/s: 1.2.12
    • Component/s: Core
    • Labels:
      None

      Description

      This statement:
      if (log.IsDebugEnabled) log.DebugFormat("x:

      {0}", 123)

      Could be nicely shortened to:
      log.Debug( m=>m("value= {0}

      ", obj.Value) );

      I'm already apache committer (NPanday Incubator Project) and would be happy to help with this interface. The simplest thing would be to offer it as static Extension-Methods to ILog.

      1. LOG4NET-290.patch
        18 kB
        Dominik Psenner
      2. LOG4NET-290-doc.patch
        63 kB
        Pavel Nedoma

        Issue Links

          Activity

          Hide
          Stefan Bodewig added a comment -

          Lars, by all means, welcome! Please join the dev list.

          Note that 3.5 is no real version and that we may very well decide to do things differently in the future.

          As long as we are trying to support so many different and old frameworks I'm reluctant to add code that would only work with 3.0 and beyond. 1.2.11 is supposed to be released soon and be backwards compatible, that's why I changed the target.

          Show
          Stefan Bodewig added a comment - Lars, by all means, welcome! Please join the dev list. Note that 3.5 is no real version and that we may very well decide to do things differently in the future. As long as we are trying to support so many different and old frameworks I'm reluctant to add code that would only work with 3.0 and beyond. 1.2.11 is supposed to be released soon and be backwards compatible, that's why I changed the target.
          Hide
          Curt Arnold added a comment -

          It looks the like original code was very concerned about the cost of boxing and unboxing an integer, array creation and a function call on calls when the level is higher than debug. If those were not of concern, you could simplify the call to

          log.DebugFormat("x:

          {0}", 123)

          You would not incur any formatting costs unless the logger was at debug or lower.

          The LogMF and LogSF helper classes in log4j present a vararg like experience while avoiding the array creation and boxing costs for the most common calls. A call using LogMF would look like

          LogMF.debug(log, "x: {0}

          ", 123);

          That call should have no array creation or boxing overhead.

          Obtaining a formatter was a very expensive operation on Java. LogMF ended up having its own implementation of the simplest use patterns for MessageFormatter and only delegating to MessageFormat when the pattern was more complex.

          It would be very interesting to see a profile of the current log4net ...Format method, compared to a lambda approach, compared to the LogMF approach.

          Show
          Curt Arnold added a comment - It looks the like original code was very concerned about the cost of boxing and unboxing an integer, array creation and a function call on calls when the level is higher than debug. If those were not of concern, you could simplify the call to log.DebugFormat("x: {0}", 123) You would not incur any formatting costs unless the logger was at debug or lower. The LogMF and LogSF helper classes in log4j present a vararg like experience while avoiding the array creation and boxing costs for the most common calls. A call using LogMF would look like LogMF.debug(log, "x: {0} ", 123); That call should have no array creation or boxing overhead. Obtaining a formatter was a very expensive operation on Java. LogMF ended up having its own implementation of the simplest use patterns for MessageFormatter and only delegating to MessageFormat when the pattern was more complex. It would be very interesting to see a profile of the current log4net ...Format method, compared to a lambda approach, compared to the LogMF approach.
          Show
          Curt Arnold added a comment - The JavaDoc for LogMF is http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/LogMF.html . The source is http://svn.apache.org/repos/asf/logging/log4j/trunk/src/main/java/org/apache/log4j/LogMF.java
          Hide
          Pavel Nedoma added a comment -

          Since I wasn't able to find any conclusion on this topic I would like "reopen" this issue. I'm using log4net in many oh my projects and quite a few of them have the need to write to log objects, whose ToString is not very cheap. To avoid unnecessary calls for configurations that have logging disabled I use lazy evaluation of ToString that depends on the fact whether the related log level is enabled or not. Instead of using if-logenabled-blocks everywhere where is such object logged I prefer more elegant way with a lambda function (e.g. Log.Debug(()=>hugeInstance.ToString()) So far I have a class with extension methods to have logging methods with a delegate in parameters, But I think that this feature could be useful for many log4net users and therefore ILog could be extended to support such signatures.
          Here is a draft (no doc comments and I think that it could be nice to also have the (delegate, exception) overload) of my solution https://gist.github.com/anonymous/783045423b1c26011ac3

          Show
          Pavel Nedoma added a comment - Since I wasn't able to find any conclusion on this topic I would like "reopen" this issue. I'm using log4net in many oh my projects and quite a few of them have the need to write to log objects, whose ToString is not very cheap. To avoid unnecessary calls for configurations that have logging disabled I use lazy evaluation of ToString that depends on the fact whether the related log level is enabled or not. Instead of using if-logenabled-blocks everywhere where is such object logged I prefer more elegant way with a lambda function (e.g. Log.Debug(()=>hugeInstance.ToString()) So far I have a class with extension methods to have logging methods with a delegate in parameters, But I think that this feature could be useful for many log4net users and therefore ILog could be extended to support such signatures. Here is a draft (no doc comments and I think that it could be nice to also have the (delegate, exception) overload) of my solution https://gist.github.com/anonymous/783045423b1c26011ac3
          Hide
          Dominik Psenner added a comment - - edited

          Hi Pavel, thanks for bumping this issue. I spent some spare minute to think about this idea and am inclined to walk along the path of this idea, but disagree on the finer details. Currently everyone can create an static extension class that implements this functionality as easy as that:

          public static class ILogExtensions
          {
          public static void FatalExt(this ILog logger, object message)

          { if (!logger.IsFatalEnabled) return; logger.Fatal(message); }

          }

          and then call that extension as:

          log.FatalExt(message);

          which semantically matches the statements:

          if(log.IsFatalEnabled)
          logger.Fatal(message);

          but does not suffer from the flaws of lambda expressions (lambda expressions are hard to understand, odd stacktraces, programming with JIT while debugging, ..). We could of course add those extensions to log4net so everyone has them in future versions. Comments?

          Show
          Dominik Psenner added a comment - - edited Hi Pavel, thanks for bumping this issue. I spent some spare minute to think about this idea and am inclined to walk along the path of this idea, but disagree on the finer details. Currently everyone can create an static extension class that implements this functionality as easy as that: public static class ILogExtensions { public static void FatalExt(this ILog logger, object message) { if (!logger.IsFatalEnabled) return; logger.Fatal(message); } } and then call that extension as: log.FatalExt(message); which semantically matches the statements: if(log.IsFatalEnabled) logger.Fatal(message); but does not suffer from the flaws of lambda expressions (lambda expressions are hard to understand, odd stacktraces, programming with JIT while debugging, ..). We could of course add those extensions to log4net so everyone has them in future versions. Comments?
          Hide
          Dominik Psenner added a comment -

          This is how a patch could look like.

          Show
          Dominik Psenner added a comment - This is how a patch could look like.
          Hide
          Pavel Nedoma added a comment -

          Thanks for fast reply, I agree with you on the lazy ToString solution using extensions. However my example was bit unfortunate, in my case there are various methods that are called to retrieve log message. (errrm, it's not that huge messy variety as it might sound from my description) Especially the case when some concatenation occurs is not that rare. Therefore I think that the lambda option could be still considered.

          About the extension class included in log4net lib - I think that's a good idea, since now I have to reference/copy my log4net extension class to each project and not all projects have the need to reference some custom common library of mine, which could include such class.

          Show
          Pavel Nedoma added a comment - Thanks for fast reply, I agree with you on the lazy ToString solution using extensions. However my example was bit unfortunate, in my case there are various methods that are called to retrieve log message. (errrm, it's not that huge messy variety as it might sound from my description) Especially the case when some concatenation occurs is not that rare. Therefore I think that the lambda option could be still considered. About the extension class included in log4net lib - I think that's a good idea, since now I have to reference/copy my log4net extension class to each project and not all projects have the need to reference some custom common library of mine, which could include such class.
          Hide
          Dominik Psenner added a comment -

          That could still be done with an extension:

          public static void FatalExt(this ILog logger, Func<object> callback)

          { if (!logger.IsFatalEnabled) return; logger.Fatal(callback()); }

          Of course these extensions would be available only for the log4net versions compiled against .NET 3.5 or .NET 4.0. This is also my biggest reason of concern. Some specific log4net libraries will contain stuff that others don't have - a terrible API decision.

          Show
          Dominik Psenner added a comment - That could still be done with an extension: public static void FatalExt(this ILog logger, Func<object> callback) { if (!logger.IsFatalEnabled) return; logger.Fatal(callback()); } Of course these extensions would be available only for the log4net versions compiled against .NET 3.5 or .NET 4.0. This is also my biggest reason of concern. Some specific log4net libraries will contain stuff that others don't have - a terrible API decision.
          Hide
          Dominik Psenner added a comment -

          I reached the decision to include the extension methods as you want them. It was easy to code the methods because they are mostly copy&paste work, but can you lend me your help with the documentation? I'm posting the patch now.

          Show
          Dominik Psenner added a comment - I reached the decision to include the extension methods as you want them. It was easy to code the methods because they are mostly copy&paste work, but can you lend me your help with the documentation? I'm posting the patch now.
          Hide
          Pavel Nedoma added a comment -

          Perfect, I'll definitely take a look and start with the documentation in following days.

          Show
          Pavel Nedoma added a comment - Perfect, I'll definitely take a look and start with the documentation in following days.
          Hide
          Pavel Nedoma added a comment -

          I had some time to go through your patch in order to start to add more XmlDoc comments. But I'd like to talk about the necessity of numerous overloads in the extension file. Do you think that it's necessary to wrap whole ILog interface inside ILogExtensions but just with the *Ext suffix? I went through core implementation and I found out, that the [level]Format(...) methods are doing the same check in LogImpl, and the [level](object...) methods do the same check in Logger class and ToString is probably called somewhere deep inside appenders. So now it makes sense to only have Lamba overload for some advanced in-place formatting, which I'd still appreciate. However I think that the content of ILogExtension should be discussed (whether to include only Lamba overloads, and if so, should we use the *Ext suffix?).

          Show
          Pavel Nedoma added a comment - I had some time to go through your patch in order to start to add more XmlDoc comments. But I'd like to talk about the necessity of numerous overloads in the extension file. Do you think that it's necessary to wrap whole ILog interface inside ILogExtensions but just with the *Ext suffix? I went through core implementation and I found out, that the [level] Format(...) methods are doing the same check in LogImpl, and the [level] (object...) methods do the same check in Logger class and ToString is probably called somewhere deep inside appenders. So now it makes sense to only have Lamba overload for some advanced in-place formatting, which I'd still appreciate. However I think that the content of ILogExtension should be discussed (whether to include only Lamba overloads, and if so, should we use the *Ext suffix?).
          Hide
          Dominik Psenner added a comment -

          It seemed sensible to me because ILog is just an interface and thus makes no assumptions on the implementation. Like this it is complete and easily explained. However, I don't mind to boil it down. Stripping the Ext suffix is out of question since the compiler will start complaining due to ambiguous method signatures whenever someone adds a "using log4net.Util;" together with a "using log4net;".

          Show
          Dominik Psenner added a comment - It seemed sensible to me because ILog is just an interface and thus makes no assumptions on the implementation. Like this it is complete and easily explained. However, I don't mind to boil it down. Stripping the Ext suffix is out of question since the compiler will start complaining due to ambiguous method signatures whenever someone adds a "using log4net.Util;" together with a "using log4net;".
          Hide
          Pavel Nedoma added a comment -

          Ok, I got the point and I like your approach. I'll start with the xml-doc part then.

          Show
          Pavel Nedoma added a comment - Ok, I got the point and I like your approach. I'll start with the xml-doc part then.
          Hide
          Pavel Nedoma added a comment - - edited

          I added XML-doc comments. Most of them are copy-paste from ILog, however there were some changes and reference fixes to be done.

          Show
          Pavel Nedoma added a comment - - edited I added XML-doc comments. Most of them are copy-paste from ILog, however there were some changes and reference fixes to be done.
          Hide
          Dominik Psenner added a comment -

          Committed fix as of revision: 1476902

          Thanks for your help! You saved me a lot of time. Feel free to close this issue if you think that there is no further work needed.

          Show
          Dominik Psenner added a comment - Committed fix as of revision: 1476902 Thanks for your help! You saved me a lot of time. Feel free to close this issue if you think that there is no further work needed.
          Hide
          Pavel Nedoma added a comment -

          Thank you for your cooperation. It seems that I can't update status of this issue, since I'm not the one who created it. But I agree with marking this issue as closed.

          Show
          Pavel Nedoma added a comment - Thank you for your cooperation. It seems that I can't update status of this issue, since I'm not the one who created it. But I agree with marking this issue as closed.
          Hide
          Dominik Psenner added a comment -

          I'm glad we were able to resolve this issue. Thanks for your help. It wouldn't have been possible for me without you doing the documentation, therefore the Kudos go back to you!

          Show
          Dominik Psenner added a comment - I'm glad we were able to resolve this issue. Thanks for your help. It wouldn't have been possible for me without you doing the documentation, therefore the Kudos go back to you!
          Hide
          Dmitry Naumov added a comment -

          I don't understand why you added cost of building lambda to logging. There were no need to write condition

          if (log.IsDebugEnabled)
          

          it's been in log4net for ages, since 1.2.8 if I remember correctly. Do not do string.Format, log4net does it for you if and only if logger is enabled:

          public virtual void DebugFormat(string format, params object[] args)
          {
              if (this.IsDebugEnabled)
              {
                  this.Logger.Log(ThisDeclaringType, this.m_levelDebug, new SystemStringFormat(CultureInfo.InvariantCulture, format, args), null);
              }
          }
          

          Now with these extensions more people will be confused about "checking for enabled" and more code will be poluted with these dummy checks.

          Show
          Dmitry Naumov added a comment - I don't understand why you added cost of building lambda to logging. There were no need to write condition if (log.IsDebugEnabled) it's been in log4net for ages, since 1.2.8 if I remember correctly. Do not do string.Format, log4net does it for you if and only if logger is enabled: public virtual void DebugFormat(string format, params object[] args) { if ( this .IsDebugEnabled) { this .Logger.Log(ThisDeclaringType, this .m_levelDebug, new SystemStringFormat(CultureInfo.InvariantCulture, format, args), null ); } } Now with these extensions more people will be confused about "checking for enabled" and more code will be poluted with these dummy checks.
          Hide
          Walden Leverich added a comment -

          Dmitry, I get where you're coming from with the "dummy checks" but it's not always a waste of time to do the check ahead of time.

          Gathering the information to pass into DebugFormat (or any of the other logging methods) can itself be expensive; you may be calculating results, doing DB I/O, calling services, etc. And to go though the time to gather all the information just to have DebugFormat short circuit return because logging is disabled is a complete waste of time. You'd be much better off checking IsDebugEnabled and then not bothering with the collection if you're not going to use it anyway.

          Like everything else, it's a balancing act. Some of our logging statements are wrapped in the if(), others are just naked calls and we let log4net worry about it.

          Show
          Walden Leverich added a comment - Dmitry, I get where you're coming from with the "dummy checks" but it's not always a waste of time to do the check ahead of time. Gathering the information to pass into DebugFormat (or any of the other logging methods) can itself be expensive; you may be calculating results, doing DB I/O, calling services, etc. And to go though the time to gather all the information just to have DebugFormat short circuit return because logging is disabled is a complete waste of time. You'd be much better off checking IsDebugEnabled and then not bothering with the collection if you're not going to use it anyway. Like everything else, it's a balancing act. Some of our logging statements are wrapped in the if(), others are just naked calls and we let log4net worry about it.
          Hide
          Dmitry Naumov added a comment -

          Walden,
          I do understand the need of lazy arguments evaluation, but there are two things I'm concerned about.
          First one I've mentioned earlier - useless code which is already exist:

          public static void DebugExt(this ILog logger, object message)
          {
              if (logger.IsDebugEnabled)
              {
                  logger.Debug(message);
              }
          }
          

          Second thing is bit harder to explain. Current logging implementation works such a good way, that if you call

          logger.InfoFormat("Type {0} not found in assembly '{1}'", typeName, assemblyName);
          

          it doesn't simply format string if INFO is enabled. It keeps template and arguments as separate things until they, as LoggingEventData inside LoggingEvent, reach appender. This allows to do quite interesting things like custom appender which writes to database and does automatic deduplication based on template part of logging event. This is similar to Serilog idea by Nicholas Blumhardt. Why am I talking about in context of recent changes? Because adding lambda like this kills whole idea:

          public static void DebugExt(this ILog logger, Func<object> callback)
          {
              if (logger.IsDebugEnabled)
              {
                  logger.Debug(callback());
              }
          }
          

          I expect that usage of this method will look like this:

          logger.DebugExt(() => string.Format("Total value is {0}", CalculateTotalValue());
          

          After that it's much harder to extract actual arguments of template.
          I understand that it is just my opinion and my case, but it was so good that log4net keeps these things (template and args) separated and I was impressed about it.

          Show
          Dmitry Naumov added a comment - Walden, I do understand the need of lazy arguments evaluation, but there are two things I'm concerned about. First one I've mentioned earlier - useless code which is already exist: public static void DebugExt( this ILog logger, object message) { if (logger.IsDebugEnabled) { logger.Debug(message); } } Second thing is bit harder to explain. Current logging implementation works such a good way, that if you call logger.InfoFormat( "Type {0} not found in assembly '{1}'" , typeName, assemblyName); it doesn't simply format string if INFO is enabled. It keeps template and arguments as separate things until they, as LoggingEventData inside LoggingEvent, reach appender. This allows to do quite interesting things like custom appender which writes to database and does automatic deduplication based on template part of logging event. This is similar to Serilog idea by Nicholas Blumhardt. Why am I talking about in context of recent changes? Because adding lambda like this kills whole idea: public static void DebugExt( this ILog logger, Func<object> callback) { if (logger.IsDebugEnabled) { logger.Debug(callback()); } } I expect that usage of this method will look like this: logger.DebugExt(() => string.Format( "Total value is {0}" , CalculateTotalValue()); After that it's much harder to extract actual arguments of template. I understand that it is just my opinion and my case, but it was so good that log4net keeps these things (template and args) separated and I was impressed about it.
          Hide
          Dominik Psenner added a comment -

          I expect that usage of this method will look like this:
          ??logger.DebugExt(() => string.Format("Total value is

          Unknown macro: {0}

          ", CalculateTotalValue());
          After that it's much harder to extract actual arguments of template.
          I understand that it is just my opinion and my case, but it was so good that log4net keeps these things (template and args) separated and I was impressed about it.

          As I see it, this signature is there for another purpose, namely to create objects that can be passed into custom object renderers such as:

          logger.DebugExt(() => new MyCustomLogObjectBasedOn(otherObjectFoo, otherObjectBar))

          without requiring to write:

          if(logger.IsDebugEnabled)

          Unknown macro: { logger.Debug(new MyCustomLogObjectBasedOn(otherObjectFoo, otherObjectBar)) }

          but still getting the performance benefits of lazy object instantiation.

          whereas this:

          logger.DebugExt(() => string.Format("Total value is

          Unknown macro: {0}

          ", CalculateTotalValue());

          will be written as:

          logger.DebugFormat("Total value is

          Unknown macro: {0}

          ", CalculateTotalValue())

          or:

          logger.DebugFormatExt("Total value is

          Unknown macro: {0}

          ", CalculateTotalValue())

          Show
          Dominik Psenner added a comment - I expect that usage of this method will look like this: ??logger.DebugExt(() => string.Format("Total value is Unknown macro: {0} ", CalculateTotalValue()); After that it's much harder to extract actual arguments of template. I understand that it is just my opinion and my case, but it was so good that log4net keeps these things (template and args) separated and I was impressed about it. As I see it, this signature is there for another purpose, namely to create objects that can be passed into custom object renderers such as: logger.DebugExt(() => new MyCustomLogObjectBasedOn(otherObjectFoo, otherObjectBar)) without requiring to write: if(logger.IsDebugEnabled) Unknown macro: { logger.Debug(new MyCustomLogObjectBasedOn(otherObjectFoo, otherObjectBar)) } but still getting the performance benefits of lazy object instantiation. whereas this: logger.DebugExt(() => string.Format("Total value is Unknown macro: {0} ", CalculateTotalValue()); will be written as: logger.DebugFormat("Total value is Unknown macro: {0} ", CalculateTotalValue()) or: logger.DebugFormatExt("Total value is Unknown macro: {0} ", CalculateTotalValue())
          Hide
          Dmitry Naumov added a comment -

          Based on assumption that ctor of MyCustomLogObjectBasedOn does no real work, I hardly see any benefits in unconditionally create new instance of anonymous class (for closure) and instance of Func for this lambda expression:

          logger.DebugExt(() => new MyCustomLogObjectBasedOn(otherObjectFoo, otherObjectBar))
          
          Show
          Dmitry Naumov added a comment - Based on assumption that ctor of MyCustomLogObjectBasedOn does no real work, I hardly see any benefits in unconditionally create new instance of anonymous class (for closure) and instance of Func for this lambda expression: logger.DebugExt(() => new MyCustomLogObjectBasedOn(otherObjectFoo, otherObjectBar))
          Hide
          Dominik Psenner added a comment -

          Whether you understand it or not, the people who requested this feature have a use case. If you're not happy with how this issue was resolved feel free to reopen the issue or create a new one describing what you would like to change.

          Show
          Dominik Psenner added a comment - Whether you understand it or not, the people who requested this feature have a use case. If you're not happy with how this issue was resolved feel free to reopen the issue or create a new one describing what you would like to change.

            People

            • Assignee:
              Dominik Psenner
              Reporter:
              Lars Corneliussen
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development