Bug 56966 - AccessLogValve's elapsed time has 15ms precision on Windows
Summary: AccessLogValve's elapsed time has 15ms precision on Windows
Status: NEW
Alias: None
Product: Tomcat 8
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 8.0.x-trunk
Hardware: PC All
: P2 enhancement (vote)
Target Milestone: ----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2014-09-11 15:36 UTC by Tom Fitzhenry
Modified: 2019-08-13 08:45 UTC (History)
1 user (show)



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Tom Fitzhenry 2014-09-11 15:36:42 UTC
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
Comment 1 Konstantin Kolinko 2014-12-01 18:14:30 UTC
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.
Comment 2 Tom Fitzhenry 2014-12-01 18:26:22 UTC
I observed the 15ms precision on Windows Server 2012 R2, the latest MS server edition.

Sorry, I should have mentioned that in the description.
Comment 3 Christopher Schultz 2014-12-01 22:20:57 UTC
Any other environmental notes? For instance, are you running on bare metal or in a virtualized environment?
Comment 4 Tom Fitzhenry 2014-12-02 12:51:12 UTC
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.
Comment 5 Christopher Schultz 2014-12-04 03:31:06 UTC
(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.
Comment 6 Mark Thomas 2016-03-03 17:14:07 UTC
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.
Comment 7 Mark Thomas 2016-03-03 17:36:10 UTC
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.
Comment 8 Mark Thomas 2016-03-04 12:09:14 UTC
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.
Comment 9 Mark Thomas 2019-03-29 21:47:39 UTC
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.
Comment 10 Michael Osipov 2019-08-12 22:31:35 UTC
(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?
Comment 11 Mark Thomas 2019-08-13 08:45:22 UTC
TOMCAT-NEXT.txt root of the repo, master branch.