Log4j 2
  1. Log4j 2
  2. LOG4J2-153

Async Logger/Appender performance improvement: provide mechanism to discover if location StackTraceElement is actually required downstream.

    Details

    • Type: Improvement Improvement
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 2.0-beta5
    • Component/s: None
    • Labels:
      None

      Description

      (update 2013 Feb 4: changed summary.
      Previous title: Add a method to the Layout interface to allow Loggers to discover if any of their Appenders need the location StackTraceElement.)


      Use Case: any asynchronous Logger or Appender has this problem:
      should it take a snapshot of the call stack (as implemented in Log4jLogEvent.getSource) or not?
      This is an expensive method (1600+ nanoseconds on a machine with 2.9GHz cores) so you only want to call it if you need it. Currently there is no way to discover if the location information is used by any of the configured layouts.

      If the Layout interface has a method that indicates whether the layout calls the LogEvent.getSource method, then the Logger can query its LoggerConfig if any of the configured Appenders has a Layout which needs location info. (Maybe boolean needsLocationInfo() would be a good name?)

      With this information, a Logger can construct Log4jLogEvents with a non-null dummy StackTraceElement location if none of the layouts downstream need location info. The non-null dummy location would prevent LogEvent.getSource from taking a call stack snapshot.

      The current AsynchAppender class would get an immediate performance boost from this, and custom asynchronous Loggers or Appenders would reap the same benefits.

        Issue Links

          Activity

          Hide
          Remko Popma added a comment -

          Verified as complete.

          Show
          Remko Popma added a comment - Verified as complete.
          Hide
          Ralph Goers added a comment -

          Patch from LOG4J2-163 applied in revision 1463078. Please verify and close.

          Show
          Ralph Goers added a comment - Patch from LOG4J2-163 applied in revision 1463078. Please verify and close.
          Hide
          Remko Popma added a comment -

          I submitted a new patch to LOG4J2-163 with an updated implementation for the above.

          Show
          Remko Popma added a comment - I submitted a new patch to LOG4J2-163 with an updated implementation for the above.
          Hide
          Remko Popma added a comment -

          It won't be a pain, I think.

          1. includeLocation not specified:
          a) sync: default = true, meaning lazy initialization, like current trunk
          b) async: default = false, emphasize performance like log4j-1.x and logback

          2. includeLocation="false"
          a) sync: still lazy initialization, take stack trace snapshot if layout requires it
          b) async: don't take stack trace snapshot

          3. includeLocation="true"
          a) sync: still lazy initialization
          b) async: take stacktrace snapshot before passing event to I/O thread

          The logger knows if it is sync or async so it can just Do The Right Thing.

          Show
          Remko Popma added a comment - It won't be a pain, I think. 1. includeLocation not specified: a) sync: default = true, meaning lazy initialization, like current trunk b) async: default = false, emphasize performance like log4j-1.x and logback 2. includeLocation="false" a) sync: still lazy initialization, take stack trace snapshot if layout requires it b) async: don't take stack trace snapshot 3. includeLocation="true" a) sync: still lazy initialization b) async: take stacktrace snapshot before passing event to I/O thread The logger knows if it is sync or async so it can just Do The Right Thing.
          Hide
          Ralph Goers added a comment -

          It seems the consensus is to use includeLocation.

          Having the default to be true all the time is OK if it is a pain to do otherwise.

          The plugin would implement an interface. Probably the only method in the interface would be a method that takes an FQCN and returns a StackTraceElement. The Plugin would then just be annotated with

          @Plugin(name="MyLocationInfo" type="Core") or type="LocationInfo"

          When creating the LogEvent we would then pass an instance of the specified plugin. When the location info is needed the plugin's method would be called to provide the info.

          Gary - if we took this approach we could create

          @Plugin(name="True" type="LocationInfo")

          which would allow the user to specify locationInfo="True" and likewise with False.

          Show
          Ralph Goers added a comment - It seems the consensus is to use includeLocation. Having the default to be true all the time is OK if it is a pain to do otherwise. The plugin would implement an interface. Probably the only method in the interface would be a method that takes an FQCN and returns a StackTraceElement. The Plugin would then just be annotated with @Plugin(name="MyLocationInfo" type="Core") or type="LocationInfo" When creating the LogEvent we would then pass an instance of the specified plugin. When the location info is needed the plugin's method would be called to provide the info. Gary - if we took this approach we could create @Plugin(name="True" type="LocationInfo") which would allow the user to specify locationInfo="True" and likewise with False.
          Hide
          Remko Popma added a comment -

          I like includeLocation for the name.

          Show
          Remko Popma added a comment - I like includeLocation for the name.
          Hide
          Remko Popma added a comment -

          Ralph, I understand what you are saying about true being the best default when logging is synchronous and false being the best default when logging asynchronously. I'll think of a way to implement it that way. Current impl in the patch for LOG4J-163 is that the default is true (locationInfo is included unless specified otherwise).

          Can you elaborate on your plugin idea? Not sure how that would work... (Is this very easy? I can imagine users not wanting to bother...)

          Show
          Remko Popma added a comment - Ralph, I understand what you are saying about true being the best default when logging is synchronous and false being the best default when logging asynchronously. I'll think of a way to implement it that way. Current impl in the patch for LOG4J-163 is that the default is true (locationInfo is included unless specified otherwise). Can you elaborate on your plugin idea? Not sure how that would work... (Is this very easy? I can imagine users not wanting to bother...)
          Hide
          Gary Gregory added a comment -

          I like the names that do not have "info" like "includeLocation" or "includeCaller" or even "includeCallSite".

          A plugin sounds nice and flexible but how realistic is it that people will need that? Can it be left a boolean and enhanced to a plugin later without breaking compatibility? Probably not... unless the value range is extended from "true|false" to "true|false|className" or some such.

          Show
          Gary Gregory added a comment - I like the names that do not have "info" like "includeLocation" or "includeCaller" or even "includeCallSite". A plugin sounds nice and flexible but how realistic is it that people will need that? Can it be left a boolean and enhanced to a plugin later without breaking compatibility? Probably not... unless the value range is extended from "true|false" to "true|false|className" or some such.
          Hide
          Ralph Goers added a comment -

          I prefer a) includeLocation, b) includeCallerInfo, or c) includeLocationInfo.

          On Loggers it makes sense for the default value to be true. In that case the information is only captured when an underlying component requests it. On AsyncLoggers and AsynchAppender it makes sense for it to default to false.

          Another possibility is instead of it being a boolean to make it be a Plugin (I just did something similar for the FlumeAppender to support encryption key generation). We would then provide a version that generates "real" caller data and another that returns empty strings. User's would then be free to provide their own plugiin.

          Show
          Ralph Goers added a comment - I prefer a) includeLocation, b) includeCallerInfo, or c) includeLocationInfo. On Loggers it makes sense for the default value to be true. In that case the information is only captured when an underlying component requests it. On AsyncLoggers and AsynchAppender it makes sense for it to default to false. Another possibility is instead of it being a boolean to make it be a Plugin (I just did something similar for the FlumeAppender to support encryption key generation). We would then provide a version that generates "real" caller data and another that returns empty strings. User's would then be free to provide their own plugiin.
          Hide
          Remko Popma added a comment -

          What should the default value be for this needsAttribute | includeCallerData attribute?
          I vote for the default to be "false" (the default is false in log4j-1.x and logback).

          Show
          Remko Popma added a comment - What should the default value be for this needsAttribute | includeCallerData attribute? I vote for the default to be "false" (the default is false in log4j-1.x and logback).
          Hide
          Remko Popma added a comment - - edited

          Logback has a similar attribute "includeCallerData" on its AsyncAppender.
          http://logback.qos.ch/manual/appenders.html#AsyncAppender

          In log4j-1.x there is an attribute "locationInfo" (based on the code, couldn't find any docs...)

          I think for us it makes sense to add this attribute to the logger element as LOG4J2-163 proposes async loggers in addition to async appenders.

          About the name, which do you think is better, "needsLocation", "locationInfo" or "includeCallerData"?
          ----------------------
          <loggers>
          <root level="info" needsLocation="true">
          <appender-ref ref="File"/>
          </root>
          </loggers>
          ----------------------
          <loggers>
          <root level="info" includeCallerData="true">
          <appender-ref ref="File"/>
          </root>
          </loggers>
          ----------------------
          <loggers>
          <root level="info" locationInfo="true">
          <appender-ref ref="File"/>
          </root>
          </loggers>

          Show
          Remko Popma added a comment - - edited Logback has a similar attribute "includeCallerData" on its AsyncAppender. http://logback.qos.ch/manual/appenders.html#AsyncAppender In log4j-1.x there is an attribute "locationInfo" (based on the code, couldn't find any docs...) I think for us it makes sense to add this attribute to the logger element as LOG4J2-163 proposes async loggers in addition to async appenders. About the name, which do you think is better, "needsLocation", "locationInfo" or "includeCallerData"? ---------------------- <loggers> <root level="info" needsLocation="true"> <appender-ref ref="File"/> </root> </loggers> ---------------------- <loggers> <root level="info" includeCallerData="true"> <appender-ref ref="File"/> </root> </loggers> ---------------------- <loggers> <root level="info" locationInfo="true"> <appender-ref ref="File"/> </root> </loggers>
          Hide
          Remko Popma added a comment -

          While working on AsyncLoggerConfig for LOG4J2-163, I was confronted with this issue again.
          Async loggers cannot lazily take a stack snapshot, they need to decide before handing off to the other thread...

          Latency of a call to Logger.log:
          root + %location pattern: ~40 microsec
          root without %location: ~5.4 microsec
          asyncRoot (with stack snapshot): ~15 microsec <--- ouch!
          asyncRoot (no stack snapshot) : 0.6 microsec

          I see 4 options:
          1. Always include location info.
          AsyncLoggerConfig would be 3x times slower than sync logger if no appender needs location, making it useless for users who don't want location info.

          2. Never include location info.
          But some users do want location info... Maybe not a real option either.

          3. Automatically detect if location is required.
          This seems difficult and requires many API and impl changes in many places

          4. Manually specify if location is required.
          This may be our most practical solution, even if not very elegant.

          I propose to add a "needsLocation" attibute to the logger and asyncLogger config. (Better name, anyone? "skip/omitLocation"? "location"?)
          The default would be to include location information.

          The only drawback I see is some added complexity around additivity with parent loggers having different needsLocation settings.

          Example config snippet:
          <loggers>
          <asyncLogger name="com.foo.Bar" level="trace" needsLocation="false">
          <appender-ref ref="File"/>
          </asyncLogger>
          <root level="info"> <!-- needsLocation not specified, so "true" by default -->
          <appender-ref ref="File"/>
          </root>
          </loggers>

          Thoughts?

          Show
          Remko Popma added a comment - While working on AsyncLoggerConfig for LOG4J2-163 , I was confronted with this issue again. Async loggers cannot lazily take a stack snapshot, they need to decide before handing off to the other thread... Latency of a call to Logger.log: root + %location pattern: ~40 microsec root without %location: ~5.4 microsec asyncRoot (with stack snapshot): ~15 microsec <--- ouch! asyncRoot (no stack snapshot) : 0.6 microsec I see 4 options: 1. Always include location info. AsyncLoggerConfig would be 3x times slower than sync logger if no appender needs location, making it useless for users who don't want location info. 2. Never include location info. But some users do want location info... Maybe not a real option either. 3. Automatically detect if location is required. This seems difficult and requires many API and impl changes in many places 4. Manually specify if location is required. This may be our most practical solution, even if not very elegant. I propose to add a "needsLocation" attibute to the logger and asyncLogger config. (Better name, anyone? "skip/omitLocation"? "location"?) The default would be to include location information. The only drawback I see is some added complexity around additivity with parent loggers having different needsLocation settings. Example config snippet: <loggers> <asyncLogger name="com.foo.Bar" level="trace" needsLocation="false"> <appender-ref ref="File"/> </asyncLogger> <root level="info"> <!-- needsLocation not specified, so "true" by default --> <appender-ref ref="File"/> </root> </loggers> Thoughts?
          Hide
          Remko Popma added a comment - - edited

          Understood. In my domain (trading applications, including low-latency trading apps), logging latency is the most important consideration, so I am biased. In practice we can always tell from the Logger name and the log message where in our code the message was generated, so we don't use location in our layout pattern.

          I am okay with any approach that has some way to avoid incurring the location cost. My preference would be to make this the default for async Loggers/Appenders, but I understand that opinions can differ on this.

          Show
          Remko Popma added a comment - - edited Understood. In my domain (trading applications, including low-latency trading apps), logging latency is the most important consideration, so I am biased. In practice we can always tell from the Logger name and the log message where in our code the message was generated, so we don't use location in our layout pattern. I am okay with any approach that has some way to avoid incurring the location cost. My preference would be to make this the default for async Loggers/Appenders, but I understand that opinions can differ on this.
          Hide
          Ralph Goers added a comment -

          Location information is extremely valuable in debug logs which, IMO, are the prime candidate for asynchronous logging, so ignoring the information doesn't seem like a good option to me.

          I'm going to think about this one as the idea is a good one. However, I am still in the midst of dealing with the ThreadContext improvement.

          Show
          Ralph Goers added a comment - Location information is extremely valuable in debug logs which, IMO, are the prime candidate for asynchronous logging, so ignoring the information doesn't seem like a good option to me. I'm going to think about this one as the idea is a good one. However, I am still in the midst of dealing with the ThreadContext improvement.
          Hide
          Remko Popma added a comment -

          I see. Looks like following this route will get complex very fast...

          Maybe I am over-engineering things, and something much simpler could accomplish the same goal.
          How about these ideas:

          1. exclude location information for async Loggers/Appenders. Reasoning: clients choose async Loggers/Appenders to decrease logging latency. Since speed is their main concern, they won't need/want the expensive location. Clients who do want location can use the standard (synchronous) Logger/Appenders.

          or
          2. exclude by default (as in #1), but have a system property that enables clients to force location information to be included in async Loggers/Appenders.

          3. any other ideas, anyone?

          Show
          Remko Popma added a comment - I see. Looks like following this route will get complex very fast... Maybe I am over-engineering things, and something much simpler could accomplish the same goal. How about these ideas: 1. exclude location information for async Loggers/Appenders. Reasoning: clients choose async Loggers/Appenders to decrease logging latency. Since speed is their main concern, they won't need/want the expensive location. Clients who do want location can use the standard (synchronous) Logger/Appenders. or 2. exclude by default (as in #1), but have a system property that enables clients to force location information to be included in async Loggers/Appenders. 3. any other ideas, anyone?
          Hide
          Ralph Goers added a comment -

          Filters and any custom class added to an Appender might also need access to the location information, so I don't think just adding a method to the Layout is the complete solution.

          Show
          Ralph Goers added a comment - Filters and any custom class added to an Appender might also need access to the location information, so I don't think just adding a method to the Layout is the complete solution.

            People

            • Assignee:
              Ralph Goers
              Reporter:
              Remko Popma
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development