Details

    • Epic Name:
      GC-free

      Description

      In certain fields like finance, predictable latency is very important, and applications in this space tend to carefully manage their object allocation to avoid unpredictable GC pauses. As of 2.5, Log4j is not suitable to be included in such applications since it allocates new objects while running in its steady state.

      This ticket is to investigate the feasibility of modifying some key components in Log4j to provide a configuration that does not allocate new objects in its steady state. (Initialization or shutdown don't need to be allocation-free.)

      To clarify, I am not proposing to make all of Log4j allocation-free. My goal is to create an allocation-free execution path in Log4j with some reasonable subset of the Log4j functionality. For example, make logging garbage-free if all of these conditions are met:

      • all loggers are AsyncLoggers
      • you only use the RandomAccessFileAppender
      • you only use a PatternLayout without any regular expression replacements, without lookups and with one of the pre-defined date formats.

      Further restrictions may be necessary.


      Update:

      The scope has been expanded to

      • include both synchronous and asynchronous loggers
      • include the most common appenders: console, file and random access file appender (both with rolling variants)

      The tickets below list separate pieces of work necessary to accomplish this.

        Issue Links

          Issues in Epic

            Activity

            Hide
            garydgregory Gary Gregory added a comment -

            We probably create too many temporary Strings out of convenience. Some judicious use of StringBuilders would help.

            Show
            garydgregory Gary Gregory added a comment - We probably create too many temporary Strings out of convenience. Some judicious use of StringBuilders would help.
            Hide
            ralph.goers@dslextreme.com Ralph Goers added a comment -

            I have no idea how you are going to avoid creating Message objects.

            Show
            ralph.goers@dslextreme.com Ralph Goers added a comment - I have no idea how you are going to avoid creating Message objects.
            Hide
            remkop@yahoo.com Remko Popma added a comment -

            In the RingBufferLogEvent, the Message objects can be pre-allocated. These Messages can be simple wrappers around a StringBuilder.

            On the producer (application) thread side, I was thinking to have a new MessageFactory that returns a ThreadLocal cached Message instance.

            When the message and other log event elements like level, timestamp etc. are enqueued in the RingBufferLogEvent, the content of the application thread-local message can be copied into the ringbuffer message. (Or they could even swap their StringBuilder instances.)

            Show
            remkop@yahoo.com Remko Popma added a comment - In the RingBufferLogEvent, the Message objects can be pre-allocated. These Messages can be simple wrappers around a StringBuilder. On the producer (application) thread side, I was thinking to have a new MessageFactory that returns a ThreadLocal cached Message instance. When the message and other log event elements like level, timestamp etc. are enqueued in the RingBufferLogEvent, the content of the application thread-local message can be copied into the ringbuffer message. (Or they could even swap their StringBuilder instances.)
            Hide
            remkop@yahoo.com Remko Popma added a comment -

            As requested in LOG4J2-1274 and LOG4J2-1278, I created a performance test that compares "classic" logging with gc-free logging. The classic test uses varargs, creating temporary ParameterizedMessages and PatternLayout; the noGC test unrolls the varargs, re-uses a StringBuilder-based Message and uses the CharEncoder API to convert text to bytes.

            Results:

            Classic[0] (2016-02-17 02:59:11.292) took 1,432,449,565 ns. CHECK=1113dda30
            Classic[1] (2016-02-17 02:59:12.839) took 1,259,734,411 ns. CHECK=1113dda30
            Classic[2] (2016-02-17 02:59:14.202) took 1,218,989,829 ns. CHECK=1113dda30
            Classic[3] (2016-02-17 02:59:15.530) took 1,209,093,017 ns. CHECK=1113dda30
            Classic[4] (2016-02-17 02:59:16.839) took 1,208,648,678 ns. CHECK=1113dda30
            Classic[5] (2016-02-17 02:59:18.145) took 1,222,321,165 ns. CHECK=1113dda30
            Classic[6] (2016-02-17 02:59:19.471) took 1,221,951,084 ns. CHECK=1113dda30
            Classic[7] (2016-02-17 02:59:20.800) took 1,388,327,159 ns. CHECK=1113dda30
            Classic[8] (2016-02-17 02:59:22.297) took 1,311,564,533 ns. CHECK=1113dda30
            Classic[9] (2016-02-17 02:59:23.710) took 1,206,745,142 ns. CHECK=1113dda30
            
            NoGC[0] (2016-02-17 02:58:44.002) took 972,486,586 ns. CHECK=1113dda30
            NoGC[1] (2016-02-17 02:58:45.081) took 923,443,846 ns. CHECK=1113dda30
            NoGC[2] (2016-02-17 02:58:46.103) took 833,296,707 ns. CHECK=1113dda30
            NoGC[3] (2016-02-17 02:58:47.032) took 809,844,530 ns. CHECK=1113dda30
            NoGC[4] (2016-02-17 02:58:47.942) took 828,931,195 ns. CHECK=1113dda30
            NoGC[5] (2016-02-17 02:58:48.880) took 818,920,279 ns. CHECK=1113dda30
            NoGC[6] (2016-02-17 02:58:49.802) took 816,935,846 ns. CHECK=1113dda30
            NoGC[7] (2016-02-17 02:58:50.724) took 818,421,605 ns. CHECK=1113dda30
            NoGC[8] (2016-02-17 02:58:51.647) took 812,101,242 ns. CHECK=1113dda30
            NoGC[9] (2016-02-17 02:58:52.554) took 848,276,857 ns. CHECK=1113dda30
            

            To verify the results, the tests can be run like this:

            // Run CLASSIC test (varargs, ParameterizedMessage, PatternLayout(%m)):
            java -Xms64M -Xmx64M -cp log4j-perf/target/benchmarks.jar -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps org.apache.logging.log4j.perf.nogc.Test Classic
            
            // Run NOGC test (unrolled varargs, StringBuilderMessage, NoGcLayout(%m)):
            java -Xms64M -Xmx64M -cp log4j-perf/target/benchmarks.jar -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps org.apache.logging.log4j.perf.nogc.Test NoGC
            
            Show
            remkop@yahoo.com Remko Popma added a comment - As requested in LOG4J2-1274 and LOG4J2-1278 , I created a performance test that compares "classic" logging with gc-free logging. The classic test uses varargs, creating temporary ParameterizedMessages and PatternLayout; the noGC test unrolls the varargs, re-uses a StringBuilder-based Message and uses the CharEncoder API to convert text to bytes. Results: Classic[0] (2016-02-17 02:59:11.292) took 1,432,449,565 ns. CHECK=1113dda30 Classic[1] (2016-02-17 02:59:12.839) took 1,259,734,411 ns. CHECK=1113dda30 Classic[2] (2016-02-17 02:59:14.202) took 1,218,989,829 ns. CHECK=1113dda30 Classic[3] (2016-02-17 02:59:15.530) took 1,209,093,017 ns. CHECK=1113dda30 Classic[4] (2016-02-17 02:59:16.839) took 1,208,648,678 ns. CHECK=1113dda30 Classic[5] (2016-02-17 02:59:18.145) took 1,222,321,165 ns. CHECK=1113dda30 Classic[6] (2016-02-17 02:59:19.471) took 1,221,951,084 ns. CHECK=1113dda30 Classic[7] (2016-02-17 02:59:20.800) took 1,388,327,159 ns. CHECK=1113dda30 Classic[8] (2016-02-17 02:59:22.297) took 1,311,564,533 ns. CHECK=1113dda30 Classic[9] (2016-02-17 02:59:23.710) took 1,206,745,142 ns. CHECK=1113dda30 NoGC[0] (2016-02-17 02:58:44.002) took 972,486,586 ns. CHECK=1113dda30 NoGC[1] (2016-02-17 02:58:45.081) took 923,443,846 ns. CHECK=1113dda30 NoGC[2] (2016-02-17 02:58:46.103) took 833,296,707 ns. CHECK=1113dda30 NoGC[3] (2016-02-17 02:58:47.032) took 809,844,530 ns. CHECK=1113dda30 NoGC[4] (2016-02-17 02:58:47.942) took 828,931,195 ns. CHECK=1113dda30 NoGC[5] (2016-02-17 02:58:48.880) took 818,920,279 ns. CHECK=1113dda30 NoGC[6] (2016-02-17 02:58:49.802) took 816,935,846 ns. CHECK=1113dda30 NoGC[7] (2016-02-17 02:58:50.724) took 818,421,605 ns. CHECK=1113dda30 NoGC[8] (2016-02-17 02:58:51.647) took 812,101,242 ns. CHECK=1113dda30 NoGC[9] (2016-02-17 02:58:52.554) took 848,276,857 ns. CHECK=1113dda30 To verify the results, the tests can be run like this: // Run CLASSIC test (varargs, ParameterizedMessage, PatternLayout(%m)): java -Xms64M -Xmx64M -cp log4j-perf/target/benchmarks.jar -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps org.apache.logging.log4j.perf.nogc.Test Classic // Run NOGC test (unrolled varargs, StringBuilderMessage, NoGcLayout(%m)): java -Xms64M -Xmx64M -cp log4j-perf/target/benchmarks.jar -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps org.apache.logging.log4j.perf.nogc.Test NoGC
            Hide
            garydgregory Gary Gregory added a comment -

            Wow, that's a big difference!

            Show
            garydgregory Gary Gregory added a comment - Wow, that's a big difference!
            Hide
            ralph.goers@dslextreme.com Ralph Goers added a comment - - edited

            Yes it is a big difference. But....

            Classic uses ParameterizedMessage while NoGC uses NoGcMessage which is much simpler. NoGcMessage also relies on having p1 through p4 as individual parameters vs varargs array, Is that realistic? I have a suspicion that most of the gains seen are happening due to these differences.

            NoGcLogger reuses the same NoGcMessage. At the very least it would have to be obtained from a ThreadLocal to be thread safe.
            Likewise, NoGcLayout uses several objects, none of which are thread-safe.

            One other thing I am concerned about is that NoGcMessage is formatting the message when it is created instead of when it is requested. I wouldn't want to see that in an actual implementation.

            Show
            ralph.goers@dslextreme.com Ralph Goers added a comment - - edited Yes it is a big difference. But.... Classic uses ParameterizedMessage while NoGC uses NoGcMessage which is much simpler. NoGcMessage also relies on having p1 through p4 as individual parameters vs varargs array, Is that realistic? I have a suspicion that most of the gains seen are happening due to these differences. NoGcLogger reuses the same NoGcMessage. At the very least it would have to be obtained from a ThreadLocal to be thread safe. Likewise, NoGcLayout uses several objects, none of which are thread-safe. One other thing I am concerned about is that NoGcMessage is formatting the message when it is created instead of when it is requested. I wouldn't want to see that in an actual implementation.
            Hide
            ralph.goers@dslextreme.com Ralph Goers added a comment -

            I don't understand how this works for arbitrary Messages.

            Show
            ralph.goers@dslextreme.com Ralph Goers added a comment - I don't understand how this works for arbitrary Messages.
            Hide
            remkop@yahoo.com Remko Popma added a comment -

            The test code is a proof of concept to give evidence of what kind of performance difference gc-free logging will make. You are quite right that it is not production-level quality yet. The final version will use ThreadLocals to be thread safe.

            I will address your concerns on the NoGcMessage class in LOG4J2-1271.

            Show
            remkop@yahoo.com Remko Popma added a comment - The test code is a proof of concept to give evidence of what kind of performance difference gc-free logging will make. You are quite right that it is not production-level quality yet. The final version will use ThreadLocals to be thread safe. I will address your concerns on the NoGcMessage class in LOG4J2-1271 .
            Hide
            ralph.goers@dslextreme.com Ralph Goers added a comment - - edited

            Actually, it occurs to me that you can't use a ThreadLocal for the Message because you can't then pass it off to another thread, so you would have to use some sort of ring buffer that allows new Messages to be allocated should the ring buffer be full.

            As I think I tried to point out, although there probably is some benefit to be had, I am pretty sure it isn't going to be nearly as dramatic as these numbers seem.

            Show
            ralph.goers@dslextreme.com Ralph Goers added a comment - - edited Actually, it occurs to me that you can't use a ThreadLocal for the Message because you can't then pass it off to another thread, so you would have to use some sort of ring buffer that allows new Messages to be allocated should the ring buffer be full. As I think I tried to point out, although there probably is some benefit to be had, I am pretty sure it isn't going to be nearly as dramatic as these numbers seem.
            Hide
            remkop@yahoo.com Remko Popma added a comment -

            You are right: this won't work for arbitrary Messages. We can only support gc-free behaviour with a limited set of Message types.

            If the users choose to also log other kinds of Messages it will mean temporary objects are created for those Messages. As long as logging still functions and things don't break, that should be fine.

            Show
            remkop@yahoo.com Remko Popma added a comment - You are right: this won't work for arbitrary Messages. We can only support gc-free behaviour with a limited set of Message types. If the users choose to also log other kinds of Messages it will mean temporary objects are created for those Messages. As long as logging still functions and things don't break, that should be fine.
            Hide
            remkop@yahoo.com Remko Popma added a comment -

            You may be right that some of the performance difference comes from the different Message implementation and I will run another test for that.

            For the existing test though, I can see 661 minor GCs during the Classic test, versus 56 during the "noGC" test (which is obviously not living up to its name yet ). That is a 13x difference.

            A minor GC only takes 300-400 microseconds of user time on my laptop, but it all adds up, and some applications (finance being one example) care about sub-millisecond latencies.

            Show
            remkop@yahoo.com Remko Popma added a comment - You may be right that some of the performance difference comes from the different Message implementation and I will run another test for that. For the existing test though, I can see 661 minor GCs during the Classic test, versus 56 during the "noGC" test (which is obviously not living up to its name yet ). That is a 13x difference. A minor GC only takes 300-400 microseconds of user time on my laptop, but it all adds up, and some applications (finance being one example) care about sub-millisecond latencies.
            Hide
            remkop@yahoo.com Remko Popma added a comment -

            Running the Classic test with NoGcMessage instead of ParameterizedMessage (creating a new instance for each log event) gives this:

            Classic[0] (2016-02-17 19:27:41.736) took 1,217,075,427 ns. CHECK=1113dda30
            Classic[1] (2016-02-17 19:27:43.055) took 1,132,891,852 ns. CHECK=1113dda30
            Classic[2] (2016-02-17 19:27:44.289) took 1,111,914,933 ns. CHECK=1113dda30
            Classic[3] (2016-02-17 19:27:45.509) took 996,953,620 ns. CHECK=1113dda30
            Classic[4] (2016-02-17 19:27:46.603) took 1,006,936,160 ns. CHECK=1113dda30
            Classic[5] (2016-02-17 19:27:47.710) took 1,001,869,726 ns. CHECK=1113dda30
            Classic[6] (2016-02-17 19:27:48.814) took 1,063,575,531 ns. CHECK=1113dda30
            Classic[7] (2016-02-17 19:27:49.986) took 1,183,842,955 ns. CHECK=1113dda30
            Classic[8] (2016-02-17 19:27:51.267) took 1,076,177,619 ns. CHECK=1113dda30
            Classic[9] (2016-02-17 19:27:52.452) took 1,024,451,338 ns. CHECK=1113dda30
            
            (539 minor GC occurrences averaging 400 us user time)
            

            This tells me two things:

            • Optimizing the Message implementation (LOG4J2-1271) can give some significant performance gains.
            • This is not the only factor, and it is still worth spending effort on reducing object allocation rate: fewer GC pauses make a large difference.
            Show
            remkop@yahoo.com Remko Popma added a comment - Running the Classic test with NoGcMessage instead of ParameterizedMessage (creating a new instance for each log event) gives this: Classic[0] (2016-02-17 19:27:41.736) took 1,217,075,427 ns. CHECK=1113dda30 Classic[1] (2016-02-17 19:27:43.055) took 1,132,891,852 ns. CHECK=1113dda30 Classic[2] (2016-02-17 19:27:44.289) took 1,111,914,933 ns. CHECK=1113dda30 Classic[3] (2016-02-17 19:27:45.509) took 996,953,620 ns. CHECK=1113dda30 Classic[4] (2016-02-17 19:27:46.603) took 1,006,936,160 ns. CHECK=1113dda30 Classic[5] (2016-02-17 19:27:47.710) took 1,001,869,726 ns. CHECK=1113dda30 Classic[6] (2016-02-17 19:27:48.814) took 1,063,575,531 ns. CHECK=1113dda30 Classic[7] (2016-02-17 19:27:49.986) took 1,183,842,955 ns. CHECK=1113dda30 Classic[8] (2016-02-17 19:27:51.267) took 1,076,177,619 ns. CHECK=1113dda30 Classic[9] (2016-02-17 19:27:52.452) took 1,024,451,338 ns. CHECK=1113dda30 (539 minor GC occurrences averaging 400 us user time) This tells me two things: Optimizing the Message implementation ( LOG4J2-1271 ) can give some significant performance gains. This is not the only factor, and it is still worth spending effort on reducing object allocation rate: fewer GC pauses make a large difference.
            Hide
            ralph.goers@dslextreme.com Ralph Goers added a comment -

            Can you do me a favor and modify NoGcLayout to use ThreadLocals to make it thread safe and then run the NoGc test again? I suspect that that will bring the times even closer together, However, it is unlikely to change the difference in the number of GCs.

            Minor GCs don't have pauses. They happen on a separate thread and don't stop the application.

            Show
            ralph.goers@dslextreme.com Ralph Goers added a comment - Can you do me a favor and modify NoGcLayout to use ThreadLocals to make it thread safe and then run the NoGc test again? I suspect that that will bring the times even closer together, However, it is unlikely to change the difference in the number of GCs. Minor GCs don't have pauses. They happen on a separate thread and don't stop the application.
            Hide
            remkop@yahoo.com Remko Popma added a comment -

            NoGC test after introducing ThreadLocal in the NoGCMessage class:

            NoGC[0] (2016-02-17 21:24:36.227) took 922,766,470 ns. CHECK=1113dda30
            NoGC[1] (2016-02-17 21:24:37.258) took 836,536,882 ns. CHECK=1113dda30
            NoGC[2] (2016-02-17 21:24:38.195) took 794,610,817 ns. CHECK=1113dda30
            NoGC[3] (2016-02-17 21:24:39.096) took 789,674,788 ns. CHECK=1113dda30
            NoGC[4] (2016-02-17 21:24:39.982) took 789,142,304 ns. CHECK=1113dda30
            NoGC[5] (2016-02-17 21:24:40.879) took 785,797,686 ns. CHECK=1113dda30
            NoGC[6] (2016-02-17 21:24:41.765) took 798,985,989 ns. CHECK=1113dda30
            NoGC[7] (2016-02-17 21:24:42.666) took 805,058,223 ns. CHECK=1113dda30
            NoGC[8] (2016-02-17 21:24:43.565) took 779,291,375 ns. CHECK=1113dda30
            NoGC[9] (2016-02-17 21:24:44.454) took 783,671,377 ns. CHECK=1113dda30
            
            56 minor GC occurrences of 300-400us user time
            
            Show
            remkop@yahoo.com Remko Popma added a comment - NoGC test after introducing ThreadLocal in the NoGCMessage class: NoGC[0] (2016-02-17 21:24:36.227) took 922,766,470 ns. CHECK=1113dda30 NoGC[1] (2016-02-17 21:24:37.258) took 836,536,882 ns. CHECK=1113dda30 NoGC[2] (2016-02-17 21:24:38.195) took 794,610,817 ns. CHECK=1113dda30 NoGC[3] (2016-02-17 21:24:39.096) took 789,674,788 ns. CHECK=1113dda30 NoGC[4] (2016-02-17 21:24:39.982) took 789,142,304 ns. CHECK=1113dda30 NoGC[5] (2016-02-17 21:24:40.879) took 785,797,686 ns. CHECK=1113dda30 NoGC[6] (2016-02-17 21:24:41.765) took 798,985,989 ns. CHECK=1113dda30 NoGC[7] (2016-02-17 21:24:42.666) took 805,058,223 ns. CHECK=1113dda30 NoGC[8] (2016-02-17 21:24:43.565) took 779,291,375 ns. CHECK=1113dda30 NoGC[9] (2016-02-17 21:24:44.454) took 783,671,377 ns. CHECK=1113dda30 56 minor GC occurrences of 300-400us user time
            Hide
            remkop@yahoo.com Remko Popma added a comment -

            In Hotspot minor collections are stop-the-world events.

            http://mechanical-sympathy.blogspot.jp/2013/07/java-garbage-collection-distilled.html

            Show
            remkop@yahoo.com Remko Popma added a comment - In Hotspot minor collections are stop-the-world events. http://mechanical-sympathy.blogspot.jp/2013/07/java-garbage-collection-distilled.html
            Hide
            ralph.goers@dslextreme.com Ralph Goers added a comment -

            Well, that is surprising. It is actually faster than your first run?

            Show
            ralph.goers@dslextreme.com Ralph Goers added a comment - Well, that is surprising. It is actually faster than your first run?
            Hide
            remkop@yahoo.com Remko Popma added a comment -

            Yes, surprised me too. I expected minimal or no change, since ThreadLocals only add a HashMap lookup. May have to do with data fitting better in L1 or L2 cache, but just speculating. If I have time tomorrow I may try to investigate further (but not a big concern, may not get around to it.)

            Show
            remkop@yahoo.com Remko Popma added a comment - Yes, surprised me too. I expected minimal or no change, since ThreadLocals only add a HashMap lookup. May have to do with data fitting better in L1 or L2 cache, but just speculating. If I have time tomorrow I may try to investigate further (but not a big concern, may not get around to it.)
            Hide
            remkop@yahoo.com Remko Popma added a comment -

            If I add -XX:+PrintGCApplicationStoppedTime to the command line options, I see this:

            ...
            13.760: [GC (Allocation Failure) [PSYoungGen: 20576K->64K(20992K)] 21997K->1485K(65024K), 0.0004359 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
            13.761: Total time for which application threads were stopped: 0.0005880 seconds, Stopping threads took: 0.0000254 seconds
            13.779: [GC (Allocation Failure) [PSYoungGen: 20544K->96K(20992K)] 21965K->1517K(65024K), 0.0003979 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
            13.780: Total time for which application threads were stopped: 0.0005433 seconds, Stopping threads took: 0.0000223 seconds
            13.797: [GC (Allocation Failure) [PSYoungGen: 20576K->64K(20992K)] 21997K->1485K(65024K), 0.0003985 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
            13.797: Total time for which application threads were stopped: 0.0005663 seconds, Stopping threads took: 0.0000241 seconds
            ...
            
            Show
            remkop@yahoo.com Remko Popma added a comment - If I add -XX:+PrintGCApplicationStoppedTime to the command line options, I see this: ... 13.760: [GC (Allocation Failure) [PSYoungGen: 20576K->64K(20992K)] 21997K->1485K(65024K), 0.0004359 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 13.761: Total time for which application threads were stopped: 0.0005880 seconds, Stopping threads took: 0.0000254 seconds 13.779: [GC (Allocation Failure) [PSYoungGen: 20544K->96K(20992K)] 21965K->1517K(65024K), 0.0003979 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 13.780: Total time for which application threads were stopped: 0.0005433 seconds, Stopping threads took: 0.0000223 seconds 13.797: [GC (Allocation Failure) [PSYoungGen: 20576K->64K(20992K)] 21997K->1485K(65024K), 0.0003985 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 13.797: Total time for which application threads were stopped: 0.0005663 seconds, Stopping threads took: 0.0000241 seconds ...
            Hide
            remkop@yahoo.com Remko Popma added a comment - - edited

            I found why the "NoGC" test was not completely GC-free: it uses Unboxer.box(double) to wrap the primitive parameters in a StringBuilder, but when building the formatted message text, the StringBuilder.append(Object) method was called instead of StringBuilder.append(StringBuilder). As Ralph pointed out in LOG4J2-1271, this means the toString method got called on the StringBuilder parameter. Ouch!

            Checking the param type with instanceof and casting to StringBuilder before appending to the formatted text StringBuilder solved the problem.

            Results:

            NoGC[0] (2016-02-18 19:15:34.130) took 803,649,416 ns. CHECK=1113dda30
            NoGC[1] (2016-02-18 19:15:35.033) took 795,524,068 ns. CHECK=1113dda30
            NoGC[2] (2016-02-18 19:15:35.935) took 764,242,400 ns. CHECK=1113dda30
            NoGC[3] (2016-02-18 19:15:36.791) took 759,120,882 ns. CHECK=1113dda30
            NoGC[4] (2016-02-18 19:15:37.648) took 760,439,465 ns. CHECK=1113dda30
            NoGC[5] (2016-02-18 19:15:38.508) took 764,538,570 ns. CHECK=1113dda30
            NoGC[6] (2016-02-18 19:15:39.372) took 769,256,005 ns. CHECK=1113dda30
            NoGC[7] (2016-02-18 19:15:40.241) took 785,887,154 ns. CHECK=1113dda30
            NoGC[8] (2016-02-18 19:15:41.131) took 758,333,986 ns. CHECK=1113dda30
            NoGC[9] (2016-02-18 19:15:41.981) took 767,727,505 ns. CHECK=1113dda30
            
            0 (zero) minor GC occurrences (yay!)
            
            Show
            remkop@yahoo.com Remko Popma added a comment - - edited I found why the "NoGC" test was not completely GC-free: it uses Unboxer.box(double) to wrap the primitive parameters in a StringBuilder, but when building the formatted message text, the StringBuilder.append(Object) method was called instead of StringBuilder.append(StringBuilder) . As Ralph pointed out in LOG4J2-1271 , this means the toString method got called on the StringBuilder parameter. Ouch! Checking the param type with instanceof and casting to StringBuilder before appending to the formatted text StringBuilder solved the problem. Results: NoGC[0] (2016-02-18 19:15:34.130) took 803,649,416 ns. CHECK=1113dda30 NoGC[1] (2016-02-18 19:15:35.033) took 795,524,068 ns. CHECK=1113dda30 NoGC[2] (2016-02-18 19:15:35.935) took 764,242,400 ns. CHECK=1113dda30 NoGC[3] (2016-02-18 19:15:36.791) took 759,120,882 ns. CHECK=1113dda30 NoGC[4] (2016-02-18 19:15:37.648) took 760,439,465 ns. CHECK=1113dda30 NoGC[5] (2016-02-18 19:15:38.508) took 764,538,570 ns. CHECK=1113dda30 NoGC[6] (2016-02-18 19:15:39.372) took 769,256,005 ns. CHECK=1113dda30 NoGC[7] (2016-02-18 19:15:40.241) took 785,887,154 ns. CHECK=1113dda30 NoGC[8] (2016-02-18 19:15:41.131) took 758,333,986 ns. CHECK=1113dda30 NoGC[9] (2016-02-18 19:15:41.981) took 767,727,505 ns. CHECK=1113dda30 0 (zero) minor GC occurrences (yay!)

              People

              • Assignee:
                Unassigned
                Reporter:
                remkop@yahoo.com Remko Popma
              • Votes:
                3 Vote for this issue
                Watchers:
                11 Start watching this issue

                Dates

                • Created:
                  Updated:

                  Development