You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by re...@apache.org on 2020/02/27 15:49:24 UTC
[tomcat] branch master updated: Update request start time using
nanoTime
This is an automated email from the ASF dual-hosted git repository.
remm pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/tomcat.git
The following commit(s) were added to refs/heads/master by this push:
new 22ad695 Update request start time using nanoTime
22ad695 is described below
commit 22ad69571c019f4d84ccc522298dddb4f8fa8d70
Author: remm <re...@apache.org>
AuthorDate: Thu Feb 27 16:49:04 2020 +0100
Update request start time using nanoTime
get/setStartTime are still there, not sure about existing use. Another
patch round could deprecate them.
Also change the access log to be the start of the request (a small part
of 63286).
---
TOMCAT-NEXT.txt | 6 ++---
.../apache/catalina/connector/CoyoteAdapter.java | 7 +++---
.../catalina/valves/AbstractAccessLogValve.java | 16 +++++--------
java/org/apache/coyote/AbstractProcessor.java | 1 +
java/org/apache/coyote/Request.java | 10 ++++++++
java/org/apache/coyote/RequestInfo.java | 28 ++++++++++++----------
java/org/apache/coyote/Response.java | 2 +-
java/org/apache/coyote/ajp/AjpProcessor.java | 1 +
.../apache/coyote/http11/Http11InputBuffer.java | 3 +++
java/org/apache/coyote/http2/Stream.java | 3 +++
webapps/docs/changelog.xml | 4 ++++
11 files changed, 50 insertions(+), 31 deletions(-)
diff --git a/TOMCAT-NEXT.txt b/TOMCAT-NEXT.txt
index ab47a46..34e3adf 100644
--- a/TOMCAT-NEXT.txt
+++ b/TOMCAT-NEXT.txt
@@ -41,11 +41,9 @@ New items for 10.0.x onwards:
4. RFC 3986 states (section 2.2) that a %nn encoded delimiter is NOT equivalent
to the decoded form. Provide an option not to decode delimiters in %nn form.
- 5. BZ 56966. Refactor internal request timing to use System.nanoTime()
+ 5. BZ 63286. Make behaviour of %D and %T consistent with httpd.
- 6. BZ 63286. Make behaviour of %D and %T consistent with httpd.
-
- 7. Refactor DefaultServlet to use Ranges in parseRanges().
+ 6. Refactor DefaultServlet to use Ranges in parseRanges().
Deferred until 10.1.x:
diff --git a/java/org/apache/catalina/connector/CoyoteAdapter.java b/java/org/apache/catalina/connector/CoyoteAdapter.java
index 1a1430b..18b8025 100644
--- a/java/org/apache/catalina/connector/CoyoteAdapter.java
+++ b/java/org/apache/catalina/connector/CoyoteAdapter.java
@@ -20,6 +20,7 @@ import java.io.IOException;
import java.nio.charset.Charset;
import java.nio.charset.StandardCharsets;
import java.util.EnumSet;
+import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicBoolean;
import jakarta.servlet.ReadListener;
@@ -273,8 +274,8 @@ public class CoyoteAdapter implements Adapter {
// Access logging
if (!success || !request.isAsync()) {
long time = 0;
- if (req.getStartTime() != -1) {
- time = System.currentTimeMillis() - req.getStartTime();
+ if (req.getStartTimeNanos() != -1) {
+ time = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - req.getStartTimeNanos());
}
Context context = request.getContext();
if (context != null) {
@@ -402,7 +403,7 @@ public class CoyoteAdapter implements Adapter {
// The other possibility is that an error occurred early in
// processing and the request could not be mapped to a Context.
// Log via the host or engine in that case.
- long time = System.currentTimeMillis() - req.getStartTime();
+ long time = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - req.getStartTimeNanos());
if (context != null) {
context.logAccess(request, response, time, false);
} else if (response.isError()) {
diff --git a/java/org/apache/catalina/valves/AbstractAccessLogValve.java b/java/org/apache/catalina/valves/AbstractAccessLogValve.java
index 47685ea..5cc1f03 100644
--- a/java/org/apache/catalina/valves/AbstractAccessLogValve.java
+++ b/java/org/apache/catalina/valves/AbstractAccessLogValve.java
@@ -30,6 +30,7 @@ import java.util.List;
import java.util.Locale;
import java.util.Map;
import java.util.TimeZone;
+import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicBoolean;
import jakarta.servlet.RequestDispatcher;
@@ -699,14 +700,9 @@ public abstract class AbstractAccessLogValve extends ValveBase implements Access
return;
}
- /**
- * XXX This is a bit silly, but we want to have start and stop time and
- * duration consistent. It would be better to keep start and stop
- * simply in the request and/or response object and remove time
- * (duration) from the interface.
- */
- long start = request.getCoyoteRequest().getStartTime();
- Date date = getDate(start + time);
+ long elapsed = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - request.getCoyoteRequest().getStartTimeNanos());
+ // Date for access log should be the beginning of the request
+ Date date = getDate(System.currentTimeMillis() - elapsed);
CharArrayWriter result = charArrayWriters.pop();
if (result == null) {
@@ -1372,8 +1368,8 @@ public abstract class AbstractAccessLogValve extends ValveBase implements Access
if (commitTime == -1) {
buf.append('-');
} else {
- long delta = commitTime - request.getCoyoteRequest().getStartTime();
- buf.append(Long.toString(delta));
+ long delta = commitTime - request.getCoyoteRequest().getStartTimeNanos();
+ buf.append(Long.toString(TimeUnit.NANOSECONDS.toMillis(delta)));
}
}
}
diff --git a/java/org/apache/coyote/AbstractProcessor.java b/java/org/apache/coyote/AbstractProcessor.java
index 254950e..5af3710 100644
--- a/java/org/apache/coyote/AbstractProcessor.java
+++ b/java/org/apache/coyote/AbstractProcessor.java
@@ -978,6 +978,7 @@ public abstract class AbstractProcessor extends AbstractProcessorLight implement
setSocketWrapper(socketWrapper);
// Setup the minimal request information
request.setStartTime(System.currentTimeMillis());
+ request.setStartTimeNanos(System.nanoTime());
// Setup the minimal response information
response.setStatus(400);
response.setError();
diff --git a/java/org/apache/coyote/Request.java b/java/org/apache/coyote/Request.java
index deff3f4..3c095cb 100644
--- a/java/org/apache/coyote/Request.java
+++ b/java/org/apache/coyote/Request.java
@@ -154,6 +154,7 @@ public final class Request {
private long bytesRead=0;
// Time of the request - useful to avoid repeated calls to System.currentTime
private long startTime = -1;
+ private long startTimeNanos = -1;
private int available = 0;
private final RequestInfo reqProcessorMX=new RequestInfo(this);
@@ -571,6 +572,14 @@ public final class Request {
this.startTime = startTime;
}
+ public long getStartTimeNanos() {
+ return startTimeNanos;
+ }
+
+ public void setStartTimeNanos(long startTimeNanos) {
+ this.startTimeNanos = startTimeNanos;
+ }
+
// -------------------- Per-Request "notes" --------------------
@@ -647,6 +656,7 @@ public final class Request {
allDataReadEventSent.set(false);
startTime = -1;
+ startTimeNanos = -1;
}
// -------------------- Info --------------------
diff --git a/java/org/apache/coyote/RequestInfo.java b/java/org/apache/coyote/RequestInfo.java
index 30216b7..23cfb27 100644
--- a/java/org/apache/coyote/RequestInfo.java
+++ b/java/org/apache/coyote/RequestInfo.java
@@ -17,6 +17,8 @@
package org.apache.coyote;
+import java.util.concurrent.TimeUnit;
+
import javax.management.ObjectName;
@@ -125,11 +127,11 @@ public class RequestInfo {
public long getRequestProcessingTime() {
// Not perfect, but good enough to avoid returning strange values due to
// concurrent updates.
- long startTime = req.getStartTime();
+ long startTime = req.getStartTimeNanos();
if (getStage() == org.apache.coyote.Constants.STAGE_ENDED || startTime < 0) {
return 0;
} else {
- return System.currentTimeMillis() - startTime;
+ return TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startTime);
}
}
@@ -153,24 +155,24 @@ public class RequestInfo {
private long lastRequestProcessingTime = 0;
- /** Called by the processor before recycling the request. It'll collect
+ /**
+ * Called by the processor before recycling the request. It'll collect
* statistic information.
*/
void updateCounters() {
- bytesReceived+=req.getBytesRead();
- bytesSent+=req.getResponse().getContentWritten();
+ bytesReceived += req.getBytesRead();
+ bytesSent += req.getResponse().getContentWritten();
requestCount++;
- if( req.getResponse().getStatus() >=400 )
+ if (req.getResponse().getStatus() >= 400) {
errorCount++;
- long t0=req.getStartTime();
- long t1=System.currentTimeMillis();
- long time=t1-t0;
+ }
+ long time = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - req.getStartTimeNanos());
this.lastRequestProcessingTime = time;
- processingTime+=time;
- if( maxTime < time ) {
- maxTime=time;
- maxRequestUri=req.requestURI().toString();
+ processingTime += time;
+ if (maxTime < time) {
+ maxTime = time;
+ maxRequestUri = req.requestURI().toString();
}
}
diff --git a/java/org/apache/coyote/Response.java b/java/org/apache/coyote/Response.java
index 54a4844..9555538 100644
--- a/java/org/apache/coyote/Response.java
+++ b/java/org/apache/coyote/Response.java
@@ -258,7 +258,7 @@ public final class Response {
public void setCommitted(boolean v) {
if (v && !this.committed) {
- this.commitTime = System.currentTimeMillis();
+ this.commitTime = System.nanoTime();
}
this.committed = v;
}
diff --git a/java/org/apache/coyote/ajp/AjpProcessor.java b/java/org/apache/coyote/ajp/AjpProcessor.java
index a333d04..562fc67 100644
--- a/java/org/apache/coyote/ajp/AjpProcessor.java
+++ b/java/org/apache/coyote/ajp/AjpProcessor.java
@@ -395,6 +395,7 @@ public class AjpProcessor extends AbstractProcessor {
break;
}
request.setStartTime(System.currentTimeMillis());
+ request.setStartTimeNanos(System.nanoTime());
} catch (IOException e) {
setErrorState(ErrorState.CLOSE_CONNECTION_NOW, e);
break;
diff --git a/java/org/apache/coyote/http11/Http11InputBuffer.java b/java/org/apache/coyote/http11/Http11InputBuffer.java
index 04543ef..59a01f7 100644
--- a/java/org/apache/coyote/http11/Http11InputBuffer.java
+++ b/java/org/apache/coyote/http11/Http11InputBuffer.java
@@ -378,6 +378,9 @@ public class Http11InputBuffer implements InputBuffer, ApplicationBufferHandler
if (request.getStartTime() < 0) {
request.setStartTime(System.currentTimeMillis());
}
+ if (request.getStartTimeNanos() < 0) {
+ request.setStartTimeNanos(System.nanoTime());
+ }
chr = byteBuffer.get();
} while ((chr == Constants.CR) || (chr == Constants.LF));
byteBuffer.position(byteBuffer.position() - 1);
diff --git a/java/org/apache/coyote/http2/Stream.java b/java/org/apache/coyote/http2/Stream.java
index 65d636d..647ddf6 100644
--- a/java/org/apache/coyote/http2/Stream.java
+++ b/java/org/apache/coyote/http2/Stream.java
@@ -132,6 +132,9 @@ class Stream extends AbstractStream implements HeaderEmitter {
if (this.coyoteRequest.getStartTime() < 0) {
this.coyoteRequest.setStartTime(System.currentTimeMillis());
}
+ if (this.coyoteRequest.getStartTimeNanos() < 0) {
+ this.coyoteRequest.setStartTimeNanos(System.nanoTime());
+ }
}
diff --git a/webapps/docs/changelog.xml b/webapps/docs/changelog.xml
index 13def23..ebe4117 100644
--- a/webapps/docs/changelog.xml
+++ b/webapps/docs/changelog.xml
@@ -91,6 +91,10 @@
A zero length AJP secret will now behave as if it has not been
specified. (remm)
</fix>
+ <update>
+ <bug>56966</bug>: Add use of System.nanoTime to track request
+ execution time. (remm)
+ </update>
</changelog>
</subsection>
<subsection name="Cluster">
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: [tomcat] branch master updated: Update request start time using nanoTime
Posted by Rémy Maucherat <re...@apache.org>.
On Thu, Feb 27, 2020 at 11:26 PM Christopher Schultz <
chris@christopherschultz.net> wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA256
>
> Rémy,
>
> On 2/27/20 17:20, Christopher Schultz wrote:
> > Rémy,
> >
> > On 2/27/20 10:49, remm@apache.org wrote:
> >> This is an automated email from the ASF dual-hosted git
> >> repository.
> >
> >> remm pushed a commit to branch master in repository
> >> https://gitbox.apache.org/repos/asf/tomcat.git
> >
> >
> >> The following commit(s) were added to refs/heads/master by this
> >> push: new 22ad695 Update request start time using nanoTime
> >> 22ad695 is described below
> >
> >> commit 22ad69571c019f4d84ccc522298dddb4f8fa8d70 Author: remm
> >> <re...@apache.org> AuthorDate: Thu Feb 27 16:49:04 2020 +0100
> >
> >> Update request start time using nanoTime
> >
> >> get/setStartTime are still there, not sure about existing use.
> >> Another patch round could deprecate them. Also change the access
> >> log to be the start of the request (a small part of 63286). ---
> >
> >> [snip]
> >
> >> diff --git a/java/org/apache/coyote/AbstractProcessor.java
> >> b/java/org/apache/coyote/AbstractProcessor.java index
> >> 254950e..5af3710 100644 ---
> >> a/java/org/apache/coyote/AbstractProcessor.java +++
> >> b/java/org/apache/coyote/AbstractProcessor.java @@ -978,6 +978,7
> >> @@ public abstract class AbstractProcessor extends
> >> AbstractProcessorLight implement
> >> setSocketWrapper(socketWrapper); // Setup the minimal request
> >> information request.setStartTime(System.currentTimeMillis()); +
> >> request.setStartTimeNanos(System.nanoTime()); // Setup the
> >> minimal response information response.setStatus(400);
> >> response.setError();
> >
> > Since we are talking about nanoseconds, here, we ARE, by
> > definition, splitting hairs :)
> >
> > System.currentTimeMillis() and System.nanoTime() may disagree when
> > you capture them like this, because [a super-small amount of] time
> > elapses between the two calls.
> >
> > Should we instead do:
> >
> > long nanos = System.nanoTime(); request.setStartTimeNanos(nanos);
> > request.setStartTime(nanos / 1000000l);
> >
> > Or maybe:
> >
> > long nanos = System.nanoTime(); request.setStartTimeNanos(nanos);
> > request.setStartTime(TimeUnit.NANOSECONDS.toMillis(nanos));
> >
> > ?
>
> Also, System.nanoTime apparently takes a lot longer than
> System.currentTimeMillis(), but it always moves forward in time, while
> System.currentTimeMillis can fall back for leap seconds, etc. and can
> behave in surprising ways :)
>
getStartTime isn't used anymore [in Tomcat itself] so it's not a big
problem. I'll try to think more about removing it, and maybe Mark will want
to redo this refactoring anyway.
Rémy
>
> - -chris
> -----BEGIN PGP SIGNATURE-----
> Comment: Using GnuPG with Thunderbird - https://www.enigmail.net/
>
> iQIzBAEBCAAdFiEEMmKgYcQvxMe7tcJcHPApP6U8pFgFAl5YQhgACgkQHPApP6U8
> pFgh4g/9GPUk5r+Lu8F2+JdhBs35v1oZwJE7D341sOcgycbVPLzoWBh2/EJvNSUS
> l+PmfkVSJNNUqMgjQU0UAtQBNEkvanTA+teGP1UyJZS1tL6dkrJAQslXbO0ReUYX
> sRzo9xHSrrBhc5CTYpfryHzEuf798zNBuQvyze84eyCT3ZQeaYm34JbQ6/QPh9XV
> GBFMWyQXK8tm7JdGrPpd9QRmTxvTyVdq327bUv4fcYnjv0OUS67illZQWCKMv1JK
> DwJpVDMzL/RtoaxGJWREuxC0L6541czgD6tEOV2dxUYSUR4OnTQAhPOr/4NvARH7
> JV3j3qzV3jiqDSwHePplAKk/i03nOTRq6wZW/D76Yg4Ut9C1p1wWWF6Dw2kTT724
> DNpcSKYHA2t4Mg09z/C7dr4gtXYQ4SbxFtvEseiHycKq5ViWpGUYs83DQjMnMwBW
> /Fw1JnZulMWxz5UkmHM+fSAsAF/njLAFBVY7cf8xhBoPok6coyOBCcsS46ymizde
> notzIXpiuWOAaqP8g1Bjzm3OYjjH2gOxKLXhfghpy7guG5NGfuL9E+KDF90KzL70
> dZsTepF0d/slGkDP/g5f9PSYwZhwsz7jAkaQbSAm68EjF1MsAQbnv+MxSBthOOP1
> y9J6g9SqCakWe8JyUrHTmtO39EMugBvW75OubbLP3c/JyIdDi94=
> =aLrh
> -----END PGP SIGNATURE-----
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: dev-help@tomcat.apache.org
>
>
Re: [tomcat] branch master updated: Update request start time using
nanoTime
Posted by Christopher Schultz <ch...@christopherschultz.net>.
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256
All,
Some interesting[1] reading:
https://steveloughran.blogspot.com/2015/09/time-on-multi-core-multi-sock
et-servers.html
- -chris
[1] For some definitions of "interesting"
On 2/27/20 17:26, Christopher Schultz wrote:
> Rémy,
>
> On 2/27/20 17:20, Christopher Schultz wrote:
>> Rémy,
>
>> On 2/27/20 10:49, remm@apache.org wrote:
>>> This is an automated email from the ASF dual-hosted git
>>> repository.
>
>>> remm pushed a commit to branch master in repository
>>> https://gitbox.apache.org/repos/asf/tomcat.git
>
>
>>> The following commit(s) were added to refs/heads/master by
>>> this push: new 22ad695 Update request start time using
>>> nanoTime 22ad695 is described below
>
>>> commit 22ad69571c019f4d84ccc522298dddb4f8fa8d70 Author: remm
>>> <re...@apache.org> AuthorDate: Thu Feb 27 16:49:04 2020 +0100
>
>>> Update request start time using nanoTime
>
>>> get/setStartTime are still there, not sure about existing use.
>>> Another patch round could deprecate them. Also change the
>>> access log to be the start of the request (a small part of
>>> 63286). ---
>
>>> [snip]
>
>>> diff --git a/java/org/apache/coyote/AbstractProcessor.java
>>> b/java/org/apache/coyote/AbstractProcessor.java index
>>> 254950e..5af3710 100644 ---
>>> a/java/org/apache/coyote/AbstractProcessor.java +++
>>> b/java/org/apache/coyote/AbstractProcessor.java @@ -978,6
>>> +978,7 @@ public abstract class AbstractProcessor extends
>>> AbstractProcessorLight implement
>>> setSocketWrapper(socketWrapper); // Setup the minimal request
>>> information request.setStartTime(System.currentTimeMillis());
>>> + request.setStartTimeNanos(System.nanoTime()); // Setup the
>>> minimal response information response.setStatus(400);
>>> response.setError();
>
>> Since we are talking about nanoseconds, here, we ARE, by
>> definition, splitting hairs :)
>
>> System.currentTimeMillis() and System.nanoTime() may disagree
>> when you capture them like this, because [a super-small amount
>> of] time elapses between the two calls.
>
>> Should we instead do:
>
>> long nanos = System.nanoTime();
>> request.setStartTimeNanos(nanos); request.setStartTime(nanos /
>> 1000000l);
>
>> Or maybe:
>
>> long nanos = System.nanoTime();
>> request.setStartTimeNanos(nanos);
>> request.setStartTime(TimeUnit.NANOSECONDS.toMillis(nanos));
>
>> ?
>
> Also, System.nanoTime apparently takes a lot longer than
> System.currentTimeMillis(), but it always moves forward in time,
> while System.currentTimeMillis can fall back for leap seconds, etc.
> and can behave in surprising ways :)
>
> -chris
>
-----BEGIN PGP SIGNATURE-----
Comment: Using GnuPG with Thunderbird - https://www.enigmail.net/
iQIzBAEBCAAdFiEEMmKgYcQvxMe7tcJcHPApP6U8pFgFAl5YQz0ACgkQHPApP6U8
pFhE6A//aCZRXyBVu5VjqeM53Sa3luTca3+Q3o70cRbefrqSpgGHVGCaCEBTFX8L
fIk1yrXE8TB9sA0C2d/SEdPK/Db0crirNTR6yQr49w5XU7a841u/wrI+Vqb3/5je
+Jhg5yRyrSZD7LNyRmXk1xudjWehCGmixMQzZuRWTN1fJZsVKe1PUHvQ4omWkQ6u
8IiPfPyY3UNPw0bCofw291i/KSP23/Hdad+QGG/7HRdJR7XZqtIG7x9x9W27m12F
4kKjNfPvtDr/TAEjVvFw35L5G5hw4oAtk1pPbXabQItieU0iY78pIFJVE/PH4fQ9
Cjn62fPXtBXy/XI1WTYDTUkkLiu69vXzN9Za1kLXvH6rJuzo+0kkbEOudknwEbHz
tTy5mGcdURv+qBloaH4PaednVeFFbVuU/vsZghh1ytNW379FvXtT3upuM+eJNPM1
US2v8TKSp3sK9kirgOWdwzAMkqXsQ7vQDGAiSZ+EMvMzn4CtOTWfaYioDvowzEIT
thc3j/XmvhQtygQAgO7fG4cRVUEnKlJ9AhWmxzl6isNSA7zBMMsYBSivRKFeyOha
61jeUhbZzituUyGjzTxFJPPlsXY4+8XnuMSRGo68ZPlkAU8ZWtrrKO4iGZ51gY3L
AN4ppdLGy6DeJM20nK21Xpjx31QW5qhcNGolL0llihWZW31hYLQ=
=yi5w
-----END PGP SIGNATURE-----
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: [tomcat] branch master updated: Update request start time using
nanoTime
Posted by Christopher Schultz <ch...@christopherschultz.net>.
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256
Rémy,
On 2/27/20 17:20, Christopher Schultz wrote:
> Rémy,
>
> On 2/27/20 10:49, remm@apache.org wrote:
>> This is an automated email from the ASF dual-hosted git
>> repository.
>
>> remm pushed a commit to branch master in repository
>> https://gitbox.apache.org/repos/asf/tomcat.git
>
>
>> The following commit(s) were added to refs/heads/master by this
>> push: new 22ad695 Update request start time using nanoTime
>> 22ad695 is described below
>
>> commit 22ad69571c019f4d84ccc522298dddb4f8fa8d70 Author: remm
>> <re...@apache.org> AuthorDate: Thu Feb 27 16:49:04 2020 +0100
>
>> Update request start time using nanoTime
>
>> get/setStartTime are still there, not sure about existing use.
>> Another patch round could deprecate them. Also change the access
>> log to be the start of the request (a small part of 63286). ---
>
>> [snip]
>
>> diff --git a/java/org/apache/coyote/AbstractProcessor.java
>> b/java/org/apache/coyote/AbstractProcessor.java index
>> 254950e..5af3710 100644 ---
>> a/java/org/apache/coyote/AbstractProcessor.java +++
>> b/java/org/apache/coyote/AbstractProcessor.java @@ -978,6 +978,7
>> @@ public abstract class AbstractProcessor extends
>> AbstractProcessorLight implement
>> setSocketWrapper(socketWrapper); // Setup the minimal request
>> information request.setStartTime(System.currentTimeMillis()); +
>> request.setStartTimeNanos(System.nanoTime()); // Setup the
>> minimal response information response.setStatus(400);
>> response.setError();
>
> Since we are talking about nanoseconds, here, we ARE, by
> definition, splitting hairs :)
>
> System.currentTimeMillis() and System.nanoTime() may disagree when
> you capture them like this, because [a super-small amount of] time
> elapses between the two calls.
>
> Should we instead do:
>
> long nanos = System.nanoTime(); request.setStartTimeNanos(nanos);
> request.setStartTime(nanos / 1000000l);
>
> Or maybe:
>
> long nanos = System.nanoTime(); request.setStartTimeNanos(nanos);
> request.setStartTime(TimeUnit.NANOSECONDS.toMillis(nanos));
>
> ?
Also, System.nanoTime apparently takes a lot longer than
System.currentTimeMillis(), but it always moves forward in time, while
System.currentTimeMillis can fall back for leap seconds, etc. and can
behave in surprising ways :)
- -chris
-----BEGIN PGP SIGNATURE-----
Comment: Using GnuPG with Thunderbird - https://www.enigmail.net/
iQIzBAEBCAAdFiEEMmKgYcQvxMe7tcJcHPApP6U8pFgFAl5YQhgACgkQHPApP6U8
pFgh4g/9GPUk5r+Lu8F2+JdhBs35v1oZwJE7D341sOcgycbVPLzoWBh2/EJvNSUS
l+PmfkVSJNNUqMgjQU0UAtQBNEkvanTA+teGP1UyJZS1tL6dkrJAQslXbO0ReUYX
sRzo9xHSrrBhc5CTYpfryHzEuf798zNBuQvyze84eyCT3ZQeaYm34JbQ6/QPh9XV
GBFMWyQXK8tm7JdGrPpd9QRmTxvTyVdq327bUv4fcYnjv0OUS67illZQWCKMv1JK
DwJpVDMzL/RtoaxGJWREuxC0L6541czgD6tEOV2dxUYSUR4OnTQAhPOr/4NvARH7
JV3j3qzV3jiqDSwHePplAKk/i03nOTRq6wZW/D76Yg4Ut9C1p1wWWF6Dw2kTT724
DNpcSKYHA2t4Mg09z/C7dr4gtXYQ4SbxFtvEseiHycKq5ViWpGUYs83DQjMnMwBW
/Fw1JnZulMWxz5UkmHM+fSAsAF/njLAFBVY7cf8xhBoPok6coyOBCcsS46ymizde
notzIXpiuWOAaqP8g1Bjzm3OYjjH2gOxKLXhfghpy7guG5NGfuL9E+KDF90KzL70
dZsTepF0d/slGkDP/g5f9PSYwZhwsz7jAkaQbSAm68EjF1MsAQbnv+MxSBthOOP1
y9J6g9SqCakWe8JyUrHTmtO39EMugBvW75OubbLP3c/JyIdDi94=
=aLrh
-----END PGP SIGNATURE-----
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: [tomcat] branch master updated: Update request start time using
nanoTime
Posted by Christopher Schultz <ch...@christopherschultz.net>.
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256
Martin,
On 2/28/20 04:44, Martin Grigorov wrote:
> Chris,
>
> On Fri, Feb 28, 2020 at 12:20 AM Christopher Schultz
> <chris@christopherschultz.net
> <ma...@christopherschultz.net>>
wrote:
>
> Rémy,
>
> On 2/27/20 10:49, remm@apache.org <ma...@apache.org> wrote:
>> This is an automated email from the ASF dual-hosted git
>> repository.
>
>> remm pushed a commit to branch master in repository
>> https://gitbox.apache.org/repos/asf/tomcat.git
>
>
>> The following commit(s) were added to refs/heads/master by this
>> push: new 22ad695 Update request start time using nanoTime
>> 22ad695 is described below
>
>> commit 22ad69571c019f4d84ccc522298dddb4f8fa8d70 Author: remm
>> <remm@apache.org <ma...@apache.org>> AuthorDate: Thu Feb
>> 27
> 16:49:04 2020 +0100
>
>> Update request start time using nanoTime
>
>> get/setStartTime are still there, not sure about existing use.
>> Another patch round could deprecate them. Also change the access
>> log to be the start of the request (a small part of 63286). ---
>
>> [snip]
>
>> diff --git a/java/org/apache/coyote/AbstractProcessor.java
>> b/java/org/apache/coyote/AbstractProcessor.java index
>> 254950e..5af3710 100644 ---
>> a/java/org/apache/coyote/AbstractProcessor.java +++
>> b/java/org/apache/coyote/AbstractProcessor.java @@ -978,6 +978,7
>> @@ public abstract class AbstractProcessor extends
>> AbstractProcessorLight implement
>> setSocketWrapper(socketWrapper); // Setup the minimal request
>> information request.setStartTime(System.currentTimeMillis()); +
>> request.setStartTimeNanos(System.nanoTime()); // Setup the
>> minimal response information response.setStatus(400);
>> response.setError();
>
> Since we are talking about nanoseconds, here, we ARE, by
> definition, splitting hairs :)
>
> System.currentTimeMillis() and System.nanoTime() may disagree when
> you capture them like this, because [a super-small amount of] time
> elapses between the two calls.
>
> Should we instead do:
>
> long nanos = System.nanoTime(); request.setStartTimeNanos(nanos);
> request.setStartTime(nanos / 1000000l);
>
> Or maybe:
>
> long nanos = System.nanoTime(); request.setStartTimeNanos(nanos);
> request.setStartTime(TimeUnit.NANOSECONDS.toMillis(nanos));
>
>
>> Those are not the same. Request#startTime
>> (System.currentTimeMillis) is the milliseconds since Epoch, i.e.
>> a complete timestamp. System.nanoTime() is just a relative time
>> that could be used to measure duration between two calls but it
>> doesn't tell you when exactly a call has happened.
Duh. Thanks for the sanity check :)
- -chris
-----BEGIN PGP SIGNATURE-----
Comment: Using GnuPG with Thunderbird - https://www.enigmail.net/
iQIzBAEBCAAdFiEEMmKgYcQvxMe7tcJcHPApP6U8pFgFAl5cDmUACgkQHPApP6U8
pFinzQ/9H80fwJ6I/pN5Ikrb3e/SW21kSWkVOkAypYV6EX0NwfIaAhz9KFYJehwS
YMj9iodMkhpfpibRg7B3dXlDPfOjsLRRadc2KQS/5/nOyh+YMfkoXpqXz8gL0ltt
eFRuUElA691lcAa/3hTsO/Lvw+NCUad/syXkvRBwJUWInmdGMGIZNCpAu2SYfga0
Gz51317tmV83RRSkXLQCc0t1cDTEhzWlv3bo6foe9elT5phGvd80PUAFSMga9RZa
94ee9jbM7QWfk/L/MdSlwiTVNOe4UXjBsFbIvVs1Eqy/4KkBlKwrP3iG7boXlAgm
NIHRWEYs0fwDQxk8fSbxoO6nKsgkX+hsySBi43OZhAdDAtK+AKMYyOFOF9QuDVKI
sKiobgDy5KA+dCVCI0k/O1DF3JYL0opeKDsOPHryvwcWQgtNXRdYWIiVyp1wHw9z
9MFlEgD4l6ncugKWRL4YzB06KS2YQxVbx+4IxeHPNqBF8PhmwdagHHT2aqXZoz36
fx8ra2q1M5kP+1DNioZ/pgr3Y1aCaWBu6J+qEvCS/UbYGPOTSto3VqcB+edfIaRU
Lknc0fshkfR1vYqUg3T//GI0BSlP9eAhf1ThEM0d7usb7mow2+e9AUF3AEERMiXn
Zsl0r/i+ZOK8lhiJgvh8/GSEwP1nreCCPvHnpqsVsRXRjF+KZZg=
=fnBR
-----END PGP SIGNATURE-----
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
Re: [tomcat] branch master updated: Update request start time using nanoTime
Posted by Martin Grigorov <mg...@apache.org>.
Chris,
On Fri, Feb 28, 2020 at 12:20 AM Christopher Schultz <
chris@christopherschultz.net> wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA256
>
> Rémy,
>
> On 2/27/20 10:49, remm@apache.org wrote:
> > This is an automated email from the ASF dual-hosted git
> > repository.
> >
> > remm pushed a commit to branch master in repository
> > https://gitbox.apache.org/repos/asf/tomcat.git
> >
> >
> > The following commit(s) were added to refs/heads/master by this
> > push: new 22ad695 Update request start time using nanoTime 22ad695
> > is described below
> >
> > commit 22ad69571c019f4d84ccc522298dddb4f8fa8d70 Author: remm
> > <re...@apache.org> AuthorDate: Thu Feb 27 16:49:04 2020 +0100
> >
> > Update request start time using nanoTime
> >
> > get/setStartTime are still there, not sure about existing use.
> > Another patch round could deprecate them. Also change the access
> > log to be the start of the request (a small part of 63286). ---
> >
> > [snip]
> >
> > diff --git a/java/org/apache/coyote/AbstractProcessor.java
> > b/java/org/apache/coyote/AbstractProcessor.java index
> > 254950e..5af3710 100644 ---
> > a/java/org/apache/coyote/AbstractProcessor.java +++
> > b/java/org/apache/coyote/AbstractProcessor.java @@ -978,6 +978,7 @@
> > public abstract class AbstractProcessor extends
> > AbstractProcessorLight implement setSocketWrapper(socketWrapper);
> > // Setup the minimal request information
> > request.setStartTime(System.currentTimeMillis()); +
> > request.setStartTimeNanos(System.nanoTime()); // Setup the minimal
> > response information response.setStatus(400); response.setError();
>
> Since we are talking about nanoseconds, here, we ARE, by definition,
> splitting hairs :)
>
> System.currentTimeMillis() and System.nanoTime() may disagree when you
> capture them like this, because [a super-small amount of] time elapses
> between the two calls.
>
> Should we instead do:
>
> long nanos = System.nanoTime();
> request.setStartTimeNanos(nanos);
> request.setStartTime(nanos / 1000000l);
>
> Or maybe:
>
> long nanos = System.nanoTime();
> request.setStartTimeNanos(nanos);
> request.setStartTime(TimeUnit.NANOSECONDS.toMillis(nanos));
>
>
Those are not the same.
Request#startTime (System.currentTimeMillis) is the milliseconds since
Epoch, i.e. a complete timestamp.
System.nanoTime() is just a relative time that could be used to measure
duration between two calls but it doesn't tell you when exactly a call has
happened.
> ?
>
> - -chris
> -----BEGIN PGP SIGNATURE-----
> Comment: Using GnuPG with Thunderbird - https://www.enigmail.net/
>
> iQIzBAEBCAAdFiEEMmKgYcQvxMe7tcJcHPApP6U8pFgFAl5YQJgACgkQHPApP6U8
> pFhTeBAAnSpEZcvd99nyNM8rjYaCuXvij+yaKjOWPq0TFoH7mhJGkWGzTeVS0RoX
> ONB23CqbhXv2lI9aOcCjlghW7cwvRXCiLU4I6WVZ8fDj2yjPVvEpccNrJLozmuof
> DgfCTx/Uc21s0UMkj6maCdxLUfZdGiBNcp7zwURLwanWhzqRfVzna1VwcQNPiws0
> eSK4R0YxrzS6Gt6i00+2e9FyqIe2tUL/hrF5/d3Zj9U4P/b17QOeC3FZfgZjdWMY
> splxjEBFx+YmgsAV56qx9uePHjtRnnO30WZEz7X8H+7AwENk6kp5qcA38q7WUkrm
> HS3EWYQC8W5dEsu7WcBqj3ZqDSpmwwJaZlSDFXh+bqL9AqEBnLutbBsl+49p6mHP
> NvvIQ/Q0sCXOhH7y8juB310yDDkKhHsqRbY2cUzK+eHrdSibESqwDLBDR59F5se/
> GQKw4J3icMdqxq69vOxfbXQ6R0PxiL984xW/bcvyH7xZt+d166+BtzyUWHX3knxH
> zv+0XUjErwIVrmXXTFDyJYNtjQUGULVdAtGqqSu6mQ+lw0Kr/6i9gqAR4/TUL202
> zr8drtkAv87UDQvJpEshmoLtq1tXIwBywtKf9XnXSA6Bgbz5kkMf4lbPWbMJdLQP
> BhoyiVA3Xcn8WN4RLCVeEqZHd28/6uWjLjvQXFmRIS8at3tYSeE=
> =WcID
> -----END PGP SIGNATURE-----
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: dev-help@tomcat.apache.org
>
>
Re: [tomcat] branch master updated: Update request start time using
nanoTime
Posted by Christopher Schultz <ch...@christopherschultz.net>.
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256
Rémy,
On 2/27/20 10:49, remm@apache.org wrote:
> This is an automated email from the ASF dual-hosted git
> repository.
>
> remm pushed a commit to branch master in repository
> https://gitbox.apache.org/repos/asf/tomcat.git
>
>
> The following commit(s) were added to refs/heads/master by this
> push: new 22ad695 Update request start time using nanoTime 22ad695
> is described below
>
> commit 22ad69571c019f4d84ccc522298dddb4f8fa8d70 Author: remm
> <re...@apache.org> AuthorDate: Thu Feb 27 16:49:04 2020 +0100
>
> Update request start time using nanoTime
>
> get/setStartTime are still there, not sure about existing use.
> Another patch round could deprecate them. Also change the access
> log to be the start of the request (a small part of 63286). ---
>
> [snip]
>
> diff --git a/java/org/apache/coyote/AbstractProcessor.java
> b/java/org/apache/coyote/AbstractProcessor.java index
> 254950e..5af3710 100644 ---
> a/java/org/apache/coyote/AbstractProcessor.java +++
> b/java/org/apache/coyote/AbstractProcessor.java @@ -978,6 +978,7 @@
> public abstract class AbstractProcessor extends
> AbstractProcessorLight implement setSocketWrapper(socketWrapper);
> // Setup the minimal request information
> request.setStartTime(System.currentTimeMillis()); +
> request.setStartTimeNanos(System.nanoTime()); // Setup the minimal
> response information response.setStatus(400); response.setError();
Since we are talking about nanoseconds, here, we ARE, by definition,
splitting hairs :)
System.currentTimeMillis() and System.nanoTime() may disagree when you
capture them like this, because [a super-small amount of] time elapses
between the two calls.
Should we instead do:
long nanos = System.nanoTime();
request.setStartTimeNanos(nanos);
request.setStartTime(nanos / 1000000l);
Or maybe:
long nanos = System.nanoTime();
request.setStartTimeNanos(nanos);
request.setStartTime(TimeUnit.NANOSECONDS.toMillis(nanos));
?
- -chris
-----BEGIN PGP SIGNATURE-----
Comment: Using GnuPG with Thunderbird - https://www.enigmail.net/
iQIzBAEBCAAdFiEEMmKgYcQvxMe7tcJcHPApP6U8pFgFAl5YQJgACgkQHPApP6U8
pFhTeBAAnSpEZcvd99nyNM8rjYaCuXvij+yaKjOWPq0TFoH7mhJGkWGzTeVS0RoX
ONB23CqbhXv2lI9aOcCjlghW7cwvRXCiLU4I6WVZ8fDj2yjPVvEpccNrJLozmuof
DgfCTx/Uc21s0UMkj6maCdxLUfZdGiBNcp7zwURLwanWhzqRfVzna1VwcQNPiws0
eSK4R0YxrzS6Gt6i00+2e9FyqIe2tUL/hrF5/d3Zj9U4P/b17QOeC3FZfgZjdWMY
splxjEBFx+YmgsAV56qx9uePHjtRnnO30WZEz7X8H+7AwENk6kp5qcA38q7WUkrm
HS3EWYQC8W5dEsu7WcBqj3ZqDSpmwwJaZlSDFXh+bqL9AqEBnLutbBsl+49p6mHP
NvvIQ/Q0sCXOhH7y8juB310yDDkKhHsqRbY2cUzK+eHrdSibESqwDLBDR59F5se/
GQKw4J3icMdqxq69vOxfbXQ6R0PxiL984xW/bcvyH7xZt+d166+BtzyUWHX3knxH
zv+0XUjErwIVrmXXTFDyJYNtjQUGULVdAtGqqSu6mQ+lw0Kr/6i9gqAR4/TUL202
zr8drtkAv87UDQvJpEshmoLtq1tXIwBywtKf9XnXSA6Bgbz5kkMf4lbPWbMJdLQP
BhoyiVA3Xcn8WN4RLCVeEqZHd28/6uWjLjvQXFmRIS8at3tYSeE=
=WcID
-----END PGP SIGNATURE-----
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org