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.

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

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.)

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).

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.

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!

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

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, 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.

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.

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

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

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.

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.

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

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

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.

Patch committed with minor changes in revision 1614404.

Please verify and close.

Verified - thank you!