Log4j 2
  1. Log4j 2
  2. LOG4J2-744

Avoid unnecessary Clock calls when TimestampMessage is logged

    Details

    • Type: Improvement Improvement
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 2.0.1
    • Component/s: None
    • Labels:
      None

      Description

      The TimestampMessage interface was introduced in LOG4J2-53 and revised for AsyncLogger in LOG4J2-455.

      I've observed that Clock.currentTimeMillis is still called which should not be necessary.

      I have two patches, one which adds JUnit tests that demonstrate the unnecessary Clock calls, and one which fixes the issue for both AsyncLogger and "traditional" configurations.

      1. LOG4J2-744-test.patch
        13 kB
        Scott Harrington
      2. LOG4J2-744.patch
        3 kB
        Scott Harrington
      3. ClockBenchmark-jdk1.7.0_45.txt
        35 kB
        Scott Harrington
      4. ClockBenchmark-jdk1.6.0_31.txt
        35 kB
        Scott Harrington
      5. ClockBenchmark.java
        13 kB
        Scott Harrington

        Activity

        Transition Time In Source Status Execution Times Last Executer Last Execution Date
        Open Open In Progress In Progress
        4d 11h 58m 1 Remko Popma 29/Jul/14 16:29
        In Progress In Progress Resolved Resolved
        54m 42s 1 Remko Popma 29/Jul/14 17:24
        Resolved Resolved Closed Closed
        9h 36m 1 Scott Harrington 30/Jul/14 03:00
        Scott Harrington made changes -
        Status Resolved [ 5 ] Closed [ 6 ]
        Hide
        Scott Harrington added a comment -

        Verified - thank you!

        Show
        Scott Harrington added a comment - Verified - thank you!
        Remko Popma made changes -
        Status In Progress [ 3 ] Resolved [ 5 ]
        Fix Version/s 2.0.1 [ 12327381 ]
        Resolution Fixed [ 1 ]
        Hide
        Remko Popma added a comment -

        Patch committed with minor changes in revision 1614404.

        Please verify and close.

        Show
        Remko Popma added a comment - Patch committed with minor changes in revision 1614404. Please verify and close.
        Remko Popma made changes -
        Status Open [ 1 ] In Progress [ 3 ]
        Remko Popma made changes -
        Assignee Remko Popma [ remkop@yahoo.com ]
        Hide
        Remko Popma added a comment - - edited

        Thanks for providing the microbenchmarks. There is a lot there, and I'm still unpacking it, experimenting with various things, but so far this is what I've found:

        Clock performance varies wildly across systems

        I added some simplified benchmarks to focus on the clocks:

        final static Clock systemClock = new SystemClock();
        @GenerateMicroBenchmark
        public long testSystemCurrentTimeMillis() {
            return System.currentTimeMillis();
        }
        @GenerateMicroBenchmark
        public long testSystemClock() {
            return systemClock.currentTimeMillis();
        }
        ...
        

        java 1.7.0_55 64 bit, Windows 7 Enterprise, Intel i5-2500 dual CPU 3.30GHz with hyperthreading on (4 virtual cores):

        java -jar target/microbenchmarks.jar ".*ClockTest.*" -f 1 -wi 5 -i 5  -tu ns -bm sample -t 4
        Benchmark                                    Mode   Samples         Mean   Mean error    Units
        b.ClockTest.testBaseline                   sample    205018        9.892        0.399    ns/op
        b.ClockTest.testCachedClock                sample    237702      147.085        1.211    ns/op
        b.ClockTest.testCoarseCachedClock          sample    235897       10.037        0.374    ns/op
        b.ClockTest.testSystemCurrentTimeMillis    sample    208701       14.626        1.074    ns/op
        b.ClockTest.testFakeClock                  sample    235691        9.520        0.371    ns/op
        b.ClockTest.testSystemClock                sample    239811       13.963        0.440    ns/op
        

        Unix:
        java 1.7.0_05 64 bit, RHEL 4.4.7-4 (Linux 2.6.32-431.e16x86_64), Intel Xeon 4 quad core X5570@2.93GHz CPUs (16 virtual cores):

        java -jar target/microbenchmarks.jar ".*ClockTest.*" -f 1 -wi 5 -i 5  -tu ns -bm sample -t 4
        Benchmark                                    Mode   Samples         Mean   Mean error    Units
        b.ClockTest.testBaseline                   sample    212362      729.093       10.132    ns/op
        b.ClockTest.testCachedClock                sample    152722      890.688        7.055    ns/op
        b.ClockTest.testCoarseCachedClock          sample    336110      632.849        2.585    ns/op
        b.ClockTest.testSystemCurrentTimeMillis    sample    258054     3174.306        9.986    ns/op
        b.ClockTest.testFakeClock                  sample    336549     1038.334        5.581    ns/op
        b.ClockTest.testSystemClock                sample    271259     3881.617       15.908    ns/op
        

        Note the massive difference for System.currentTimeMillis(): 14 nanos on WIndows, 3.1 micros on Linux. That's 220x!

        I agree, it looks like CachedClock performs very badly if there is contention on the volatile field. (It does perform well on the Linux box where there are enough cores to spread the load, but on the Windows box, brr...)

        To instanceof or not, that is the question

        First, I am assuming that the vast majority of users will log a mixture of SimpleMessages and ParameterizedMessages, and that TimestampMessages are a relatively rare use case.

        Here are my measurements:

        java 1.7.0_55 64 bit, Windows 7 Enterprise, Intel i5-2500 dual CPU 3.30GHz with hyperthreading on (4 virtual cores):

        java -jar target/microbenchmarks.jar ".*ClockBench.*" -f 1 -wi 5 -i 5  -tu ns -bm sample -t 4
        Benchmark                                                       Mode   Samples         Mean   Mean error    Units
        b.ClockBenchmark.testSystemClockSimpleMessageInstanceOf       sample    244944      105.317        6.183    ns/op
        b.ClockBenchmark.testSystemClockSimpleMessageUseClock         sample    284839       86.625        2.427    ns/op
        b.ClockBenchmark.testSystemClockTimestampMessageInstanceOf    sample    250178       61.812        6.151    ns/op
        

        On Windows, my results seem to indicate that the overhead of msg instanceof TimestampMessage ? ((TimestampMessage) msg).getTimestamp() : clock.currentTimeMillis() is about 20 nanos. On the other hand, TimestampMessage.getTimestamp() is about 20 nanos faster than SystemClock.currentTimeMillis().

        So just looking at my Windows results, I would not want to make logging 20 nanos slower for the majority of users in order to make logging 20 nanos faster for the fraction who log TimestampMessages.

        However, the Linux results show a very different picture. The Linux benchmark results were very noisy so I changed to 20 iterations, but results easily vary by several hundred nanoseconds between runs...

        java 1.7.0_05 64 bit, RHEL 4.4.7-4 (Linux 2.6.32-431.e16x86_64), Intel Xeon 4 quad core X5570@2.93GHz CPUs (16 virtual cores):

        java -jar target/microbenchmarks.jar ".*ClockBench.*" -f 1 -wi 5 -i 20  -tu ns -bm sample -t 4
        Benchmark                                                       Mode   Samples         Mean   Mean error    Units
        b.ClockBenchmark.testSystemClockSimpleMessageInstanceOf       sample    964501     3596.031       23.931    ns/op
        b.ClockBenchmark.testSystemClockSimpleMessageUseClock         sample    777443     3207.301       28.671    ns/op
        b.ClockBenchmark.testSystemClockTimestampMessageInstanceOf    sample    959701      720.979       12.551    ns/op
        

        On the linux box I tested on, the cost of calling System.currentTimeMillis completely dominates the cost of creating a log event. This is painful for TimestampMessages. It looks like the cost of instanceof + conditional is ~400 nanos, but in other tests I got the opposite result so I'm putting this down to noise.

        Even if the results are noisy, clearly there is a 4-5x improvement to be had by avoiding calls to System.currentTimeMillis(). The overhead of instanceof + conditional is hard to determine.

        So, to conclude, I'll put in the instanceof check.

        Show
        Remko Popma added a comment - - edited Thanks for providing the microbenchmarks. There is a lot there, and I'm still unpacking it, experimenting with various things, but so far this is what I've found: Clock performance varies wildly across systems I added some simplified benchmarks to focus on the clocks: final static Clock systemClock = new SystemClock(); @GenerateMicroBenchmark public long testSystemCurrentTimeMillis() { return System .currentTimeMillis(); } @GenerateMicroBenchmark public long testSystemClock() { return systemClock.currentTimeMillis(); } ... java 1.7.0_55 64 bit, Windows 7 Enterprise, Intel i5-2500 dual CPU 3.30GHz with hyperthreading on (4 virtual cores): java -jar target/microbenchmarks.jar ".*ClockTest.*" -f 1 -wi 5 -i 5 -tu ns -bm sample -t 4 Benchmark Mode Samples Mean Mean error Units b.ClockTest.testBaseline sample 205018 9.892 0.399 ns/op b.ClockTest.testCachedClock sample 237702 147.085 1.211 ns/op b.ClockTest.testCoarseCachedClock sample 235897 10.037 0.374 ns/op b.ClockTest.testSystemCurrentTimeMillis sample 208701 14.626 1.074 ns/op b.ClockTest.testFakeClock sample 235691 9.520 0.371 ns/op b.ClockTest.testSystemClock sample 239811 13.963 0.440 ns/op Unix: java 1.7.0_05 64 bit, RHEL 4.4.7-4 (Linux 2.6.32-431.e16x86_64), Intel Xeon 4 quad core X5570@2.93GHz CPUs (16 virtual cores): java -jar target/microbenchmarks.jar ".*ClockTest.*" -f 1 -wi 5 -i 5 -tu ns -bm sample -t 4 Benchmark Mode Samples Mean Mean error Units b.ClockTest.testBaseline sample 212362 729.093 10.132 ns/op b.ClockTest.testCachedClock sample 152722 890.688 7.055 ns/op b.ClockTest.testCoarseCachedClock sample 336110 632.849 2.585 ns/op b.ClockTest.testSystemCurrentTimeMillis sample 258054 3174.306 9.986 ns/op b.ClockTest.testFakeClock sample 336549 1038.334 5.581 ns/op b.ClockTest.testSystemClock sample 271259 3881.617 15.908 ns/op Note the massive difference for System.currentTimeMillis() : 14 nanos on WIndows, 3.1 micros on Linux. That's 220x! I agree, it looks like CachedClock performs very badly if there is contention on the volatile field. (It does perform well on the Linux box where there are enough cores to spread the load, but on the Windows box, brr...) To instanceof or not, that is the question First, I am assuming that the vast majority of users will log a mixture of SimpleMessages and ParameterizedMessages, and that TimestampMessages are a relatively rare use case. Here are my measurements: java 1.7.0_55 64 bit, Windows 7 Enterprise, Intel i5-2500 dual CPU 3.30GHz with hyperthreading on (4 virtual cores): java -jar target/microbenchmarks.jar ".*ClockBench.*" -f 1 -wi 5 -i 5 -tu ns -bm sample -t 4 Benchmark Mode Samples Mean Mean error Units b.ClockBenchmark.testSystemClockSimpleMessageInstanceOf sample 244944 105.317 6.183 ns/op b.ClockBenchmark.testSystemClockSimpleMessageUseClock sample 284839 86.625 2.427 ns/op b.ClockBenchmark.testSystemClockTimestampMessageInstanceOf sample 250178 61.812 6.151 ns/op On Windows, my results seem to indicate that the overhead of msg instanceof TimestampMessage ? ((TimestampMessage) msg).getTimestamp() : clock.currentTimeMillis() is about 20 nanos. On the other hand, TimestampMessage.getTimestamp() is about 20 nanos faster than SystemClock.currentTimeMillis() . So just looking at my Windows results, I would not want to make logging 20 nanos slower for the majority of users in order to make logging 20 nanos faster for the fraction who log TimestampMessages. However, the Linux results show a very different picture. The Linux benchmark results were very noisy so I changed to 20 iterations, but results easily vary by several hundred nanoseconds between runs... java 1.7.0_05 64 bit, RHEL 4.4.7-4 (Linux 2.6.32-431.e16x86_64), Intel Xeon 4 quad core X5570@2.93GHz CPUs (16 virtual cores): java -jar target/microbenchmarks.jar ".*ClockBench.*" -f 1 -wi 5 -i 20 -tu ns -bm sample -t 4 Benchmark Mode Samples Mean Mean error Units b.ClockBenchmark.testSystemClockSimpleMessageInstanceOf sample 964501 3596.031 23.931 ns/op b.ClockBenchmark.testSystemClockSimpleMessageUseClock sample 777443 3207.301 28.671 ns/op b.ClockBenchmark.testSystemClockTimestampMessageInstanceOf sample 959701 720.979 12.551 ns/op On the linux box I tested on, the cost of calling System.currentTimeMillis completely dominates the cost of creating a log event. This is painful for TimestampMessages. It looks like the cost of instanceof + conditional is ~400 nanos, but in other tests I got the opposite result so I'm putting this down to noise. Even if the results are noisy, clearly there is a 4-5x improvement to be had by avoiding calls to System.currentTimeMillis(). The overhead of instanceof + conditional is hard to determine. So, to conclude, I'll put in the instanceof check.
        Scott Harrington made changes -
        Attachment ClockBenchmark-jdk1.6.0_31.txt [ 12658226 ]
        Hide
        Scott Harrington added a comment -

        Summary of results for Java 6 (full results attached). Similar numbers as Java 7.

        Benchmark                                                                   Mode   Samples         Mean   Mean error    Units
        o.a.l.l.p.j.ClockBenchmark.testBaseline                                   sample    236376       28.708        0.068    ns/op
        o.a.l.l.p.j.ClockBenchmark.testCachedClockSimpleMessage                   sample    194881      480.207        2.354    ns/op
        o.a.l.l.p.j.ClockBenchmark.testCachedClockSimpleMessageNoDowncast         sample    260867      185.352        0.479    ns/op
        o.a.l.l.p.j.ClockBenchmark.testCachedClockTimestampMessage                sample    277257       64.729        0.221    ns/op
        o.a.l.l.p.j.ClockBenchmark.testCoarseCachedClockSimpleMessage             sample    383724       83.279        0.191    ns/op
        o.a.l.l.p.j.ClockBenchmark.testCoarseCachedClockSimpleMessageNoDowncast   sample    379254       82.977        0.169    ns/op
        o.a.l.l.p.j.ClockBenchmark.testCoarseCachedClockTimestampMessage          sample    273283       66.129        0.151    ns/op
        o.a.l.l.p.j.ClockBenchmark.testFakeClockSimpleMessage                     sample    274039      104.556        0.279    ns/op
        o.a.l.l.p.j.ClockBenchmark.testFakeClockSimpleMessageNoDowncast           sample    363139       88.456        4.470    ns/op
        o.a.l.l.p.j.ClockBenchmark.testFakeClockTimestampMessage                  sample    274962       65.897        0.214    ns/op
        o.a.l.l.p.j.ClockBenchmark.testOrdinaryLogEvent                           sample    206789      132.297        0.643    ns/op
        o.a.l.l.p.j.ClockBenchmark.testSystemClockSimpleMessage                   sample    201981      136.891        9.946    ns/op
        o.a.l.l.p.j.ClockBenchmark.testSystemClockSimpleMessageNoDowncast         sample    231942      120.551        0.367    ns/op
        o.a.l.l.p.j.ClockBenchmark.testSystemClockTimestampMessage                sample    267079       66.281        0.206    ns/op
        
        Show
        Scott Harrington added a comment - Summary of results for Java 6 (full results attached). Similar numbers as Java 7. Benchmark Mode Samples Mean Mean error Units o.a.l.l.p.j.ClockBenchmark.testBaseline sample 236376 28.708 0.068 ns/op o.a.l.l.p.j.ClockBenchmark.testCachedClockSimpleMessage sample 194881 480.207 2.354 ns/op o.a.l.l.p.j.ClockBenchmark.testCachedClockSimpleMessageNoDowncast sample 260867 185.352 0.479 ns/op o.a.l.l.p.j.ClockBenchmark.testCachedClockTimestampMessage sample 277257 64.729 0.221 ns/op o.a.l.l.p.j.ClockBenchmark.testCoarseCachedClockSimpleMessage sample 383724 83.279 0.191 ns/op o.a.l.l.p.j.ClockBenchmark.testCoarseCachedClockSimpleMessageNoDowncast sample 379254 82.977 0.169 ns/op o.a.l.l.p.j.ClockBenchmark.testCoarseCachedClockTimestampMessage sample 273283 66.129 0.151 ns/op o.a.l.l.p.j.ClockBenchmark.testFakeClockSimpleMessage sample 274039 104.556 0.279 ns/op o.a.l.l.p.j.ClockBenchmark.testFakeClockSimpleMessageNoDowncast sample 363139 88.456 4.470 ns/op o.a.l.l.p.j.ClockBenchmark.testFakeClockTimestampMessage sample 274962 65.897 0.214 ns/op o.a.l.l.p.j.ClockBenchmark.testOrdinaryLogEvent sample 206789 132.297 0.643 ns/op o.a.l.l.p.j.ClockBenchmark.testSystemClockSimpleMessage sample 201981 136.891 9.946 ns/op o.a.l.l.p.j.ClockBenchmark.testSystemClockSimpleMessageNoDowncast sample 231942 120.551 0.367 ns/op o.a.l.l.p.j.ClockBenchmark.testSystemClockTimestampMessage sample 267079 66.281 0.206 ns/op
        Scott Harrington made changes -
        Attachment ClockBenchmark-jdk1.7.0_45.txt [ 12658225 ]
        Hide
        Scott Harrington added a comment -

        Summary of results for Java 7 (full JMH output attached). Looks like the 'instanceof' downcast adds about 10-20ns to a 85-125ns Log4jLogEvent constructor. Ignore CachedClock which seems to suffer from thread contention (I configured this JMH run to use 4 threads).

        CentOS 6.5 on E5-2667 v2 @ 3.30GHz

        Benchmark                                                                   Mode   Samples         Mean   Mean error    Units
        o.a.l.l.p.j.ClockBenchmark.testBaseline                                   sample    238251       27.986        0.132    ns/op
        o.a.l.l.p.j.ClockBenchmark.testCachedClockSimpleMessage                   sample    265004      546.528        2.022    ns/op
        o.a.l.l.p.j.ClockBenchmark.testCachedClockSimpleMessageNoDowncast         sample    265057      192.856        0.531    ns/op
        o.a.l.l.p.j.ClockBenchmark.testCachedClockTimestampMessage                sample    278932       65.167        0.191    ns/op
        o.a.l.l.p.j.ClockBenchmark.testCoarseCachedClockSimpleMessage             sample    358047       85.017        0.122    ns/op
        o.a.l.l.p.j.ClockBenchmark.testCoarseCachedClockSimpleMessageNoDowncast   sample    366842       84.530        0.168    ns/op
        o.a.l.l.p.j.ClockBenchmark.testCoarseCachedClockTimestampMessage          sample    255360       69.229        0.208    ns/op
        o.a.l.l.p.j.ClockBenchmark.testFakeClockSimpleMessage                     sample    272217      105.782        0.199    ns/op
        o.a.l.l.p.j.ClockBenchmark.testFakeClockSimpleMessageNoDowncast           sample    365182       85.052        0.165    ns/op
        o.a.l.l.p.j.ClockBenchmark.testFakeClockTimestampMessage                  sample    286814       65.450        0.282    ns/op
        o.a.l.l.p.j.ClockBenchmark.testOrdinaryLogEvent                           sample    199051      136.273        0.277    ns/op
        o.a.l.l.p.j.ClockBenchmark.testSystemClockSimpleMessage                   sample    297985      135.690        0.312    ns/op
        o.a.l.l.p.j.ClockBenchmark.testSystemClockSimpleMessageNoDowncast         sample    235139      124.363        0.176    ns/op
        o.a.l.l.p.j.ClockBenchmark.testSystemClockTimestampMessage                sample    290519       64.377        0.231    ns/op
        
        Show
        Scott Harrington added a comment - Summary of results for Java 7 (full JMH output attached). Looks like the 'instanceof' downcast adds about 10-20ns to a 85-125ns Log4jLogEvent constructor. Ignore CachedClock which seems to suffer from thread contention (I configured this JMH run to use 4 threads). CentOS 6.5 on E5-2667 v2 @ 3.30GHz Benchmark Mode Samples Mean Mean error Units o.a.l.l.p.j.ClockBenchmark.testBaseline sample 238251 27.986 0.132 ns/op o.a.l.l.p.j.ClockBenchmark.testCachedClockSimpleMessage sample 265004 546.528 2.022 ns/op o.a.l.l.p.j.ClockBenchmark.testCachedClockSimpleMessageNoDowncast sample 265057 192.856 0.531 ns/op o.a.l.l.p.j.ClockBenchmark.testCachedClockTimestampMessage sample 278932 65.167 0.191 ns/op o.a.l.l.p.j.ClockBenchmark.testCoarseCachedClockSimpleMessage sample 358047 85.017 0.122 ns/op o.a.l.l.p.j.ClockBenchmark.testCoarseCachedClockSimpleMessageNoDowncast sample 366842 84.530 0.168 ns/op o.a.l.l.p.j.ClockBenchmark.testCoarseCachedClockTimestampMessage sample 255360 69.229 0.208 ns/op o.a.l.l.p.j.ClockBenchmark.testFakeClockSimpleMessage sample 272217 105.782 0.199 ns/op o.a.l.l.p.j.ClockBenchmark.testFakeClockSimpleMessageNoDowncast sample 365182 85.052 0.165 ns/op o.a.l.l.p.j.ClockBenchmark.testFakeClockTimestampMessage sample 286814 65.450 0.282 ns/op o.a.l.l.p.j.ClockBenchmark.testOrdinaryLogEvent sample 199051 136.273 0.277 ns/op o.a.l.l.p.j.ClockBenchmark.testSystemClockSimpleMessage sample 297985 135.690 0.312 ns/op o.a.l.l.p.j.ClockBenchmark.testSystemClockSimpleMessageNoDowncast sample 235139 124.363 0.176 ns/op o.a.l.l.p.j.ClockBenchmark.testSystemClockTimestampMessage sample 290519 64.377 0.231 ns/op
        Scott Harrington made changes -
        Attachment ClockBenchmark.java [ 12658224 ]
        Hide
        Scott Harrington added a comment -

        Drop the attached file into log4j-perf/src/main/java/org/apache/logging/log4j/perf and then 'mvn install' in log4j-perf and run the multi-thread test command line I put into the class comment. Feel free to add more/different tests.

        It may turn out that neither the Clock or instanceof are very significant compared to the ThreadLocal accesses for ContextMap and ContextStack. However these things all add up so I agree it's bad to make everyone pay the 'instanceof' penalty (however small) if an API revision (to be debated) could make it work better for everyone.

        I'm running it now and will attach my results.

        Show
        Scott Harrington added a comment - Drop the attached file into log4j-perf/src/main/java/org/apache/logging/log4j/perf and then 'mvn install' in log4j-perf and run the multi-thread test command line I put into the class comment. Feel free to add more/different tests. It may turn out that neither the Clock or instanceof are very significant compared to the ThreadLocal accesses for ContextMap and ContextStack. However these things all add up so I agree it's bad to make everyone pay the 'instanceof' penalty (however small) if an API revision (to be debated) could make it work better for everyone. I'm running it now and will attach my results.
        Hide
        Ralph Goers added a comment - - edited

        It is listed right on the wiki home page for Logging. http://wiki.apache.org/logging/Log4j2ReleaseGuide. However, there a couple of items that need to be updated as there are some sub-projects that need to be deleted from Nexus before releasing that aren't listed on the wiki.

        Show
        Ralph Goers added a comment - - edited It is listed right on the wiki home page for Logging. http://wiki.apache.org/logging/Log4j2ReleaseGuide . However, there a couple of items that need to be updated as there are some sub-projects that need to be deleted from Nexus before releasing that aren't listed on the wiki.
        Hide
        Gary Gregory added a comment -

        I thought we had a "Releasing Log4j" wiki somewhere, but now I cannot find it... Ralph?

        Show
        Gary Gregory added a comment - I thought we had a "Releasing Log4j" wiki somewhere, but now I cannot find it... Ralph?
        Hide
        Gary Gregory added a comment -

        Fat fingers, edited "fail" -> "fair" !

        Show
        Gary Gregory added a comment - Fat fingers, edited "fail" -> "fair" !
        Hide
        Matt Sicker added a comment -

        In that case, I'd have to agree with Remko's analysis and defer this to a performance test to see if instanceof is indeed fast enough to use. Tests in JDK 1.6, 1.7, and 1.8 would be nice, but 1.6 is the important one here.

        Show
        Matt Sicker added a comment - In that case, I'd have to agree with Remko's analysis and defer this to a performance test to see if instanceof is indeed fast enough to use. Tests in JDK 1.6, 1.7, and 1.8 would be nice, but 1.6 is the important one here.
        Hide
        Ralph Goers added a comment -

        Gary, I don't understand your comment about it being a "fail" to ask first. If you aren't sure of something it is ALWAYS best to ask first rather than mistakes.

        I really don't like adding any kind of timestamp method to the Message interface since it only applies to a special kind of Message.

        Show
        Ralph Goers added a comment - Gary, I don't understand your comment about it being a "fail" to ask first. If you aren't sure of something it is ALWAYS best to ask first rather than mistakes. I really don't like adding any kind of timestamp method to the Message interface since it only applies to a special kind of Message.
        Hide
        Matt Sicker added a comment -

        I'll volunteer to RM 2.0.1 as long as there are directions somewhere. Plus I'll probably need some karma or whatever. Either way, I've got some free time this week.

        Show
        Matt Sicker added a comment - I'll volunteer to RM 2.0.1 as long as there are directions somewhere. Plus I'll probably need some karma or whatever. Either way, I've got some free time this week.
        Gary Gregory made changes -
        Summary Aviod unnecessary Clock calls when TimestampMessage is logged Avoid unnecessary Clock calls when TimestampMessage is logged
        Hide
        Matt Sicker added a comment -

        Good point. I hadn't considered other ways it could be interpreted.

        Show
        Matt Sicker added a comment - Good point. I hadn't considered other ways it could be interpreted.
        Hide
        Gary Gregory added a comment - - edited

        I think isTimestampSet() is more clear. To me, hasTimestamp() answers the question "Do you carry a timestamp of any kind?" as opposed to "Is your timestamp value set?". If an object has no timestamp, a return value of false makes sense.

        But this new API makes me think of 2.1, not 2.0.1.

        I think either we do this and call the next release 2.1, or of us volunteers as RM for 2.0.1 since Ralph is going to be busy moving and getting surgery. Well, one of you, I am packing boxes to move as well!

        Show
        Gary Gregory added a comment - - edited I think isTimestampSet() is more clear. To me, hasTimestamp() answers the question "Do you carry a timestamp of any kind?" as opposed to "Is your timestamp value set?". If an object has no timestamp, a return value of false makes sense. But this new API makes me think of 2.1, not 2.0.1. I think either we do this and call the next release 2.1, or of us volunteers as RM for 2.0.1 since Ralph is going to be busy moving and getting surgery. Well, one of you, I am packing boxes to move as well!
        Hide
        Matt Sicker added a comment -

        Message could have a hasTimestamp() method to indicate if it already has a timestamp associated with it or not. This could also be be used by pre-filling the timestamp in a Message. It would basically be like LogEvent in this case. You could also pass along a generated log message without losing the associated timestamp that may wish to be associated with it.

        Show
        Matt Sicker added a comment - Message could have a hasTimestamp() method to indicate if it already has a timestamp associated with it or not. This could also be be used by pre-filling the timestamp in a Message. It would basically be like LogEvent in this case. You could also pass along a generated log message without losing the associated timestamp that may wish to be associated with it.
        Hide
        Gary Gregory added a comment - - edited

        I don't think this use case is strong enough to justify an API change.

        I think it is fair to ask first if it is the best solution. If it is, we can talk about when to implement it or discuss an alternative is the API is to disruptive for current users (with "disruptive" not defined to strictly BC).

        Show
        Gary Gregory added a comment - - edited I don't think this use case is strong enough to justify an API change. I think it is fair to ask first if it is the best solution. If it is, we can talk about when to implement it or discuss an alternative is the API is to disruptive for current users (with "disruptive" not defined to strictly BC).
        Hide
        Remko Popma added a comment -

        Gary, interesting question... I'm not sure actually. My guess would be yes, but would need to measure to be sure.

        However, it if is okay to add a method to the Message interface, I would prefer to add a method Message.getTimestamp(IClock). Most messages would return clock.currentTimeMillis(), but TimestampMessages would return this.getTimestamp(). Performance-wise this would be ideal since it would eliminate the need for conditional branching.

        (On the other hand, I don't think this use case is strong enough to justify an API change.)

        Show
        Remko Popma added a comment - Gary, interesting question... I'm not sure actually. My guess would be yes, but would need to measure to be sure. However, it if is okay to add a method to the Message interface, I would prefer to add a method Message.getTimestamp(IClock) . Most messages would return clock.currentTimeMillis(), but TimestampMessages would return this.getTimestamp(). Performance-wise this would be ideal since it would eliminate the need for conditional branching. (On the other hand, I don't think this use case is strong enough to justify an API change.)
        Hide
        Gary Gregory added a comment -

        If Message were to define an isTimestampMessage() method, would that be faster than instanceof?

        Show
        Gary Gregory added a comment - If Message were to define an isTimestampMessage() method, would that be faster than instanceof ?
        Hide
        Remko Popma added a comment -

        You are correct that this is happening, and I see how the patch would fix the problem, but I am not sure yet if I want to apply the patch.

        The patch proposes to use instanceof to check if the message is a TimestampMessage, and avoid the call to clock.currentTimeMillis() if that is the case.

        This sometimes avoids the overhead of calling clock.currentTimeMillis(), but in return always adds the overhead of calling instanceof. I am aware that instanceof is pretty damn fast nowadays, but I still hesitate to optimize for TimestampMessages (a special case) at the expense of all other message types...

        I would like to do some performance testing first. If the cost of clock.currentTimeMillis() is similar to instanceof, there may not be much benefit, even for TimestampMessages.

        Show
        Remko Popma added a comment - You are correct that this is happening, and I see how the patch would fix the problem, but I am not sure yet if I want to apply the patch. The patch proposes to use instanceof to check if the message is a TimestampMessage , and avoid the call to clock.currentTimeMillis() if that is the case. This sometimes avoids the overhead of calling clock.currentTimeMillis() , but in return always adds the overhead of calling instanceof . I am aware that instanceof is pretty damn fast nowadays, but I still hesitate to optimize for TimestampMessages (a special case) at the expense of all other message types... I would like to do some performance testing first. If the cost of clock.currentTimeMillis() is similar to instanceof , there may not be much benefit, even for TimestampMessages.
        Scott Harrington made changes -
        Field Original Value New Value
        Attachment LOG4J2-744.patch [ 12657763 ]
        Attachment LOG4J2-744-test.patch [ 12657764 ]
        Scott Harrington created issue -

          People

          • Assignee:
            Remko Popma
            Reporter:
            Scott Harrington
          • Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development