Log4j 2
  1. Log4j 2
  2. LOG4J2-628

Cannot set log4j.Clock with Async appender

    Details

    • Type: Question Question
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-rc1
    • Fix Version/s: 2.0-rc2
    • Component/s: Appenders
    • Labels:
      None
    • Environment:

      Ubuntu 12.04 / Java 7

      Description

      I override log4j.Clock to support a "live" time vs a "simulated" time.

      System.setProperty("log4j.Clock", "teambh.trade.utils.MyClock");

      If I use asynchronous loggers, it works fine and calls my Clock:currentTimeMillis().

      If I switch to async appenders, currentTimeMillis() is not called.

      Is this expected behavior or a bug?

      Thanks

        Activity

        Bryan Hsueh created issue -
        Hide
        Remko Popma added a comment -

        This is expected behaviour as of RC-1.

        The use case for the Clock interface was to allow an extra performance optimization for users who want to squeeze the last drop of performance out of the logging subsystem. The trade-off is that the faster CachedClock implementation shows jumps of 10-16 milliseconds, so you lose accuracy in the log timestamps.

        However this optimization only becomes visible after other bottlenecks have been removed. The performance bottleneck of Async appender is on the queue, and optimizing the timestamping mechanism would not make a visible difference in performance.

        If your use case for using a custom Clock is not performance related, can you clarify what it is you are trying to achieve?
        Perhaps it would make sense to use the Clock interface consistently everywhere in Log4j.

        Show
        Remko Popma added a comment - This is expected behaviour as of RC-1. The use case for the Clock interface was to allow an extra performance optimization for users who want to squeeze the last drop of performance out of the logging subsystem. The trade-off is that the faster CachedClock implementation shows jumps of 10-16 milliseconds, so you lose accuracy in the log timestamps. However this optimization only becomes visible after other bottlenecks have been removed. The performance bottleneck of Async appender is on the queue, and optimizing the timestamping mechanism would not make a visible difference in performance. If your use case for using a custom Clock is not performance related, can you clarify what it is you are trying to achieve? Perhaps it would make sense to use the Clock interface consistently everywhere in Log4j.
        Hide
        Bryan Hsueh added a comment -

        Correct, my use case is not performance related. Instead, I implement Clock so that I can decide whether to use System time or my own artificial, simulated time.

        I am simulating a program against historical data. So, when I run historically, I want to see my historical timestamp. When I run live, I want to see the System timestamp. My Clock:currentTimeMillis() decides this for me.

        Show
        Bryan Hsueh added a comment - Correct, my use case is not performance related. Instead, I implement Clock so that I can decide whether to use System time or my own artificial, simulated time. I am simulating a program against historical data. So, when I run historically, I want to see my historical timestamp. When I run live, I want to see the System timestamp. My Clock:currentTimeMillis() decides this for me.
        Remko Popma made changes -
        Field Original Value New Value
        Assignee Remko Popma [ remkop@yahoo.com ]
        Hide
        Remko Popma added a comment -

        Understood. We are thinking about modifying log4j to use the Clock interface to generate timestamps for all log events, not just the log events generated by Async Loggers.

        Question: do you also want to use that Clock interface to determine the rollover time in the RolloverAppender?

        Show
        Remko Popma added a comment - Understood. We are thinking about modifying log4j to use the Clock interface to generate timestamps for all log events, not just the log events generated by Async Loggers. Question: do you also want to use that Clock interface to determine the rollover time in the RolloverAppender?
        Hide
        Ralph Goers added a comment -

        I don't think using a fictional clock will work out to well when rolling over files as the file will have a time stamp set by the OS.

        Show
        Ralph Goers added a comment - I don't think using a fictional clock will work out to well when rolling over files as the file will have a time stamp set by the OS.
        Hide
        Remko Popma added a comment -

        I agree. Also, using the Clock interface for rollover would introduce some interesting scenarios like the clock going back in time etc that the rollover logic was not designed for. It may work, but I would prefer to keep the scope of this change limited to just the log event timestamps for now.

        Show
        Remko Popma added a comment - I agree. Also, using the Clock interface for rollover would introduce some interesting scenarios like the clock going back in time etc that the rollover logic was not designed for. It may work, but I would prefer to keep the scope of this change limited to just the log event timestamps for now.
        Hide
        Bryan Hsueh added a comment -

        Sorry, I don't use the RolloverAppender, so I'll have to defer to your comments here. Thanks.

        Show
        Bryan Hsueh added a comment - Sorry, I don't use the RolloverAppender, so I'll have to defer to your comments here. Thanks.
        Remko Popma made changes -
        Status Open [ 1 ] In Progress [ 3 ]
        Hide
        Remko Popma added a comment -

        Fixed in revision 1592242.

        The Clock interface is now used to generate all log event timestamps, not just for Async Loggers.
        Please verify and close.

        Show
        Remko Popma added a comment - Fixed in revision 1592242. The Clock interface is now used to generate all log event timestamps, not just for Async Loggers. Please verify and close.
        Remko Popma made changes -
        Resolution Fixed [ 1 ]
        Status In Progress [ 3 ] Resolved [ 5 ]
        Fix Version/s 2.0-rc2 [ 12326292 ]
        Hide
        Bryan Hsueh added a comment -

        Tested, and works, thanks. I see this message log 7 times at the start though, "ERROR StatusLogger Unable to locate ServletContext". Does this have to do with my build process? Likewise, I can no longer find SocketServer. I pulled your revision from github and followed the build instructions.

        Show
        Bryan Hsueh added a comment - Tested, and works, thanks. I see this message log 7 times at the start though, "ERROR StatusLogger Unable to locate ServletContext". Does this have to do with my build process? Likewise, I can no longer find SocketServer. I pulled your revision from github and followed the build instructions.
        Hide
        Remko Popma added a comment -

        Bryan, good to hear that.
        About the error, we are currently refactoring the code base to move web stuff into a separate module (and separate jar).
        Apparently there are still issues with that.

        Show
        Remko Popma added a comment - Bryan, good to hear that. About the error, we are currently refactoring the code base to move web stuff into a separate module (and separate jar). Apparently there are still issues with that.
        Bryan Hsueh made changes -
        Status Resolved [ 5 ] Closed [ 6 ]
        Hide
        Remko Popma added a comment -

        Bryan, SocketServer has been refactored and renamed to AbstractSocketServer in the same (core.net) package.
        The error message you mention has been modified to an info-level message yesterday. If you check out trunk again the error should go away.

        Show
        Remko Popma added a comment - Bryan, SocketServer has been refactored and renamed to AbstractSocketServer in the same (core.net) package. The error message you mention has been modified to an info-level message yesterday. If you check out trunk again the error should go away.
        Hide
        Gary Gregory added a comment -

        Please note that I am working on the whole server side of Log4j to receive JSON and XML events. This is not in trunk yet. If would kindly request that you consider delaying commits in this area if possible to make my keeping up with trunk less painful. Thank you. Gary.

        Show
        Gary Gregory added a comment - Please note that I am working on the whole server side of Log4j to receive JSON and XML events. This is not in trunk yet. If would kindly request that you consider delaying commits in this area if possible to make my keeping up with trunk less painful. Thank you. Gary.
        Transition Time In Source Status Execution Times Last Executer Last Execution Date
        Open Open In Progress In Progress
        2d 17h 1m 1 Remko Popma 03/May/14 17:24
        In Progress In Progress Resolved Resolved
        6m 19s 1 Remko Popma 03/May/14 17:30
        Resolved Resolved Closed Closed
        2d 7h 10m 1 Bryan Hsueh 06/May/14 00:40

          People

          • Assignee:
            Remko Popma
            Reporter:
            Bryan Hsueh
          • Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development