You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by bu...@apache.org on 2014/09/11 17:36:42 UTC
[Bug 56966] New: AccessLogValve's elapsed time has 15ms precision on
Windows
https://issues.apache.org/bugzilla/show_bug.cgi?id=56966
Bug ID: 56966
Summary: AccessLogValve's elapsed time has 15ms precision on
Windows
Product: Tomcat 8
Version: trunk
Hardware: PC
Status: NEW
Severity: normal
Priority: P2
Component: Catalina
Assignee: dev@tomcat.apache.org
Reporter: tom@tom-fitzhenry.me.uk
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
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 56966] AccessLogValve's elapsed time has 15ms precision on
Windows
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=56966
--- Comment #5 from Christopher Schultz <ch...@christopherschultz.net> ---
(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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 56966] AccessLogValve's elapsed time has 15ms precision on
Windows
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=56966
Konstantin Kolinko <kn...@gmail.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
OS| |All
Severity|normal |enhancement
--- Comment #1 from Konstantin Kolinko <kn...@gmail.com> ---
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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 56966] AccessLogValve's elapsed time has 15ms precision on
Windows
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=56966
--- Comment #2 from Tom Fitzhenry <to...@tom-fitzhenry.me.uk> ---
I observed the 15ms precision on Windows Server 2012 R2, the latest MS server
edition.
Sorry, I should have mentioned that in the description.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 56966] AccessLogValve's elapsed time has 15ms precision on
Windows
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=56966
--- Comment #3 from Christopher Schultz <ch...@christopherschultz.net> ---
Any other environmental notes? For instance, are you running on bare metal or
in a virtualized environment?
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 56966] AccessLogValve's elapsed time has 15ms precision on
Windows
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=56966
Tom Fitzhenry <to...@tom-fitzhenry.me.uk> changed:
What |Removed |Added
----------------------------------------------------------------------------
OS|All |Windows Server 2012
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 56966] AccessLogValve's elapsed time has 15ms precision on
Windows
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=56966
--- Comment #4 from Tom Fitzhenry <to...@tom-fitzhenry.me.uk> ---
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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 56966] AccessLogValve's elapsed time has 15ms precision on
Windows
Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=56966
Tom Fitzhenry <to...@tom-fitzhenry.me.uk> changed:
What |Removed |Added
----------------------------------------------------------------------------
CC| |tom@tom-fitzhenry.me.uk
OS| |All
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org