[Bug 56966] AccessLogValve's elapsed time has 15ms precision on Windows

[bugzilla]

https://bz.apache.org/bugzilla/show_bug.cgi?id=56966

Remy Maucherat  changed:

   What|Removed |Added

 Resolution|--- |FIXED
 Status|NEW |RESOLVED

--- Comment #12 from Remy Maucherat  ---
Added a nanoTime based API in Tomcat 10.

-- 
You are receiving this mail because:
You are the assignee for the bug.
-
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org

[Bug 56966] AccessLogValve's elapsed time has 15ms precision on Windows

[bugzilla]

https://bz.apache.org/bugzilla/show_bug.cgi?id=56966

--- Comment #11 from Mark Thomas  ---
TOMCAT-NEXT.txt root of the repo, master branch.

-- 
You are receiving this mail because:
You are the assignee for the bug.
-
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org

[Bug 56966] AccessLogValve's elapsed time has 15ms precision on Windows

[bugzilla]

https://bz.apache.org/bugzilla/show_bug.cgi?id=56966

--- Comment #10 from Michael Osipov  ---
(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?

-- 
You are receiving this mail because:
You are the assignee for the bug.
-
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org

[Bug 56966] AccessLogValve's elapsed time has 15ms precision on Windows

[bugzilla]

https://bz.apache.org/bugzilla/show_bug.cgi?id=56966

--- Comment #9 from Mark Thomas  ---
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.

-- 
You are receiving this mail because:
You are the assignee for the bug.
-
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org

[Bug 56966] AccessLogValve's elapsed time has 15ms precision on Windows

[bugzilla]

https://bz.apache.org/bugzilla/show_bug.cgi?id=56966

--- Comment #8 from Mark Thomas  ---
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.

-- 
You are receiving this mail because:
You are the assignee for the bug.
-
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org

[Bug 56966] AccessLogValve's elapsed time has 15ms precision on Windows

[bugzilla]

https://bz.apache.org/bugzilla/show_bug.cgi?id=56966

--- Comment #7 from Mark Thomas  ---
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.

-- 
You are receiving this mail because:
You are the assignee for the bug.
-
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org

[Bug 56966] AccessLogValve's elapsed time has 15ms precision on Windows

[bugzilla]

https://bz.apache.org/bugzilla/show_bug.cgi?id=56966

--- Comment #6 from Mark Thomas  ---
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.

-- 
You are receiving this mail because:
You are the assignee for the bug.
-
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org

[Bug 56966] AccessLogValve's elapsed time has 15ms precision on Windows

[bugzilla]

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-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org

[Bug 56966] AccessLogValve's elapsed time has 15ms precision on Windows

[bugzilla]

https://issues.apache.org/bugzilla/show_bug.cgi?id=56966

--- Comment #4 from Tom Fitzhenry t...@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-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org

[Bug 56966] AccessLogValve's elapsed time has 15ms precision on Windows

[bugzilla]

https://issues.apache.org/bugzilla/show_bug.cgi?id=56966

Konstantin Kolinko knst.koli...@gmail.com changed:

   What|Removed |Added

 OS||All
   Severity|normal  |enhancement

--- Comment #1 from Konstantin Kolinko knst.koli...@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-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org

[Bug 56966] AccessLogValve's elapsed time has 15ms precision on Windows

[bugzilla]

https://issues.apache.org/bugzilla/show_bug.cgi?id=56966

--- Comment #2 from Tom Fitzhenry t...@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-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org

[Bug 56966] AccessLogValve's elapsed time has 15ms precision on Windows

[bugzilla]

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-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org

[Bug 56966] AccessLogValve's elapsed time has 15ms precision on Windows

[bugzilla]

https://issues.apache.org/bugzilla/show_bug.cgi?id=56966

Tom Fitzhenry t...@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-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org

[Bug 56966] AccessLogValve's elapsed time has 15ms precision on Windows

[bugzilla]

https://issues.apache.org/bugzilla/show_bug.cgi?id=56966

Tom Fitzhenry t...@tom-fitzhenry.me.uk changed:

   What|Removed |Added

 CC||t...@tom-fitzhenry.me.uk
 OS||All

-- 
You are receiving this mail because:
You are the assignee for the bug.

-
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org