The problem: AccessLogValve's elapsed time variables (%D and %T) calculate elapsed time using System.currentTimeMillis()[0]. System.currentTimeMillis() only has a precision of ~15ms on Windows.[1] A potential fix: Calculate elapsed time using a precision timer, such as System.nanoTime(), which has a higher precision (dependent on OS). References: 0. See https://github.com/apache/tomcat/blob/3986c5dc894fda541aa1855503debe1a8c01fc9f/java/org/apache/catalina/connector/CoyoteAdapter.java#L266 , which gets fed into the 'time' parameter of https://github.com/apache/tomcat/blob/99029882cb020f8d354ad4e2ef46e8edacb0c73d/java/org/apache/catalina/valves/AbstractAccessLogValve.java#L1183 1. http://stackoverflow.com/questions/7859019/system-currenttimemillis-is-not-accurate-on-windows-xp
I see 1ms precision when running on Windows 7. I see 1ms running on Linux. The last time when I observed 10ms was Windows XP, but Windows XP is now End-of-life. Note that System.nanoTime() has caveats. It makes sense only when measuring time intervals. It cannot be used to measure current time. req.getStartTime() is used as wall clock time value. It means that there has to be another field in addition to req.getStartTime(). It also means that there needs to be a change to the Log interface to pass a nano time value in addition to milli time one. Is there much interest in measuring times shorter than 1ms? Usually there is an interest in requests that take a long time.
I observed the 15ms precision on Windows Server 2012 R2, the latest MS server edition. Sorry, I should have mentioned that in the description.
Any other environmental notes? For instance, are you running on bare metal or in a virtualized environment?
The machine is a virtual machine running on the Windows Azure hypervisor (similar to Hyper-V, supposedly). The guest OS runs Windows Server 2012 R2, and reports its hardware as: Processor: Intel(R) Xeon(R) CPU E5-2660 0 @ 2.260GHz 2.20GHz Installed memory (RAM): 14.0 GB System type: 60-bit Operation System, x64-based processor The program on http://stackoverflow.com/questions/7859019/system-currenttimemillis-is-not-accurate-on-windows-xp , when executed against Oracle JRE 7, prints 15ms.
(In reply to Konstantin Kolinko from comment #1) > I see 1ms precision when running on Windows 7. I see 1ms running on Linux. > The last time when I observed 10ms was Windows XP, but Windows XP is now > End-of-life. +1 I don't have any non-virtual Windows instances available for testing, unfortunately. I don't trust real-time clocks on VMs. > Note that System.nanoTime() has caveats. It makes sense only when measuring > time intervals. It cannot be used to measure current time. > > req.getStartTime() is used as wall clock time value. It means that there has > to be another field in addition to req.getStartTime(). It also means that > there needs to be a change to the Log interface to pass a nano time value in > addition to milli time one. AccessLogValve could take its own timestamps in nanos, though the start time would be "after" req.getStartTime(). Or we could use (nanos / 1000) to get "better" resolution for the time-interval for a request. It seems like extra work for little benefit. (Though those experiencing 15ms-minimums would certainly argue that the benefit is great.) > Is there much interest in measuring times shorter than 1ms? Usually there is > an interest in requests that take a long time. +1 For resources that run reasonably faster than 15ms, one can use a Filter around them to collect metrics and aggregate total time over many requests to get a mean-request-time if that's what you ultimately want.
System.nanoTime() is approximately 40x slower than System.currentTimeMillis(). On my machine the equates to the difference between ~600ns and ~15ns per call. Duration requires a start and an end time. So that is ~1.2μs. On the same machine a basic request with access logging takes ~30μs so switching to ns precision adds approximately 4% of overhead. That is a fair amount overhead. It is worth checking the timings on a more modern machine (I'll do that shortly) before making any decisions on this.
Hmm. Both methods around 40μs on may newer laptop which would make this change pretty much zero perofromnace impact. There are a few too many variables here. H/W, OS, JVM etc. I'm going to do some wider testing to get a better sense of the relative performance of these methods.
The times were consistent on my fairly old (2008) server running Win 2008 R2 at 15/600 regardless with Java 7 Java 8 and Java 9. On my 2012 OSX laptop the times were consistently ~40μs for Java 7 and 8. And on a year old Windows laptop the times are ~7μs for System.currentTimeMillis() and ~14μs for System.nanoTime() for Java 8 and 9. It looks like times are largely independent of Java version. On remotely modern hardware (would anyone really worried about a few μs of performance be running 4+ year old hardware?) it looks like this is a non-issue performance wise. I'm going to go ahead and implement this for 9.0.x.
The API changes to implement this mean it needs to wait for a new major version. I have added it to the 10.0.x TODO list.
(In reply to Mark Thomas from comment #9) > The API changes to implement this mean it needs to wait for a new major > version. I have added it to the 10.0.x TODO list. Can you please share the todo list?
TOMCAT-NEXT.txt root of the repo, master branch.
Added a nanoTime based API in Tomcat 10.