From 2d08e4d8f9ef4c3ac90b924e0e3a7ab2f5e1bfd2 Mon Sep 17 00:00:00 2001 From: Michael Gorovoy Date: Fri, 4 Jun 2010 05:05:30 +0000 Subject: [PATCH] 293222 Improve request log to handle/show asynchronous latency git-svn-id: svn+ssh://dev.eclipse.org/svnroot/rt/org.eclipse.jetty/jetty/trunk@1916 7e9141cc-0065-0410-87d8-b60c137991c4 --- VERSION.txt | 1 + .../eclipse/jetty/server/NCSARequestLog.java | 35 ++++++++++++++++++- .../org/eclipse/jetty/server/Request.java | 23 +++++++++++- .../server/handler/RequestLogHandler.java | 22 ++++++++++-- 4 files changed, 76 insertions(+), 5 deletions(-) diff --git a/VERSION.txt b/VERSION.txt index 17b00982fec..9289ad7dc29 100644 --- a/VERSION.txt +++ b/VERSION.txt @@ -1,6 +1,7 @@ jetty-7.1.4-SNAPSHOT + 292326 Stop continuations if server is stopped. + 292814 Make QoSFilter and DoSFilter JMX manageable + + 293222 Improve request log to handle/show asynchronous latency + 294212 Can not customize session cookie path + 302350 org.eclipse.jetty.server.NCSARequestLog is missing JavaDoc + 304100 Better document JMX setup in jetty-jmx.xml diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/NCSARequestLog.java b/jetty-server/src/main/java/org/eclipse/jetty/server/NCSARequestLog.java index 6e028af43ec..f90e7818fc2 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/NCSARequestLog.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/NCSARequestLog.java @@ -61,6 +61,7 @@ public class NCSARequestLog extends AbstractLifeCycle implements RequestLog private boolean _logLatency = false; private boolean _logCookies = false; private boolean _logServer = false; + private boolean _logDispatch = false; private transient OutputStream _out; private transient OutputStream _fileOut; @@ -416,6 +417,29 @@ public class NCSARequestLog extends AbstractLifeCycle implements RequestLog return _filenameDateFormat; } + /* ------------------------------------------------------------ */ + /** + * Controls logging of the request dispatch time + * + * @param value true - request dispatch time will be logged + * false - request dispatch time will not be logged + */ + public void setLogDispatch(boolean value) + { + _logDispatch = value; + } + + /* ------------------------------------------------------------ */ + /** + * Retrieve request dispatch time logging flag + * + * @return value of the flag + */ + public boolean isLogDispatch() + { + return _logDispatch; + } + /* ------------------------------------------------------------ */ /** * Writes the request and response information to the output stream. @@ -568,11 +592,20 @@ public class NCSARequestLog extends AbstractLifeCycle implements RequestLog _writer.write('\"'); } } + + final long now = System.currentTimeMillis(); + final long start = request.getTimeStamp(); + final long dispatch = request.getDispatchTime(); + if (_logDispatch) + { + _writer.write(' '); + _writer.write(Long.toString(now - (dispatch==0 ? start:dispatch))); + } if (_logLatency) { _writer.write(' '); - _writer.write(Long.toString(System.currentTimeMillis() - request.getTimeStamp())); + _writer.write(Long.toString(now - start)); } _writer.write(StringUtil.__LINE_SEPARATOR); diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/Request.java b/jetty-server/src/main/java/org/eclipse/jetty/server/Request.java index d73b4ec7b91..f013d874ae4 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/Request.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/Request.java @@ -155,7 +155,8 @@ public class Request implements HttpServletRequest private HttpSession _session; private SessionManager _sessionManager; private long _timeStamp; - + private long _dispatchTime; + private Buffer _timeStampBuffer; private HttpURI _uri; @@ -1210,6 +1211,16 @@ public class Request implements HttpServletRequest return null; } + /* ------------------------------------------------------------ */ + /** Get timestamp of the request dispatch + * + * @return timestamp + */ + public long getDispatchTime() + { + return _dispatchTime; + } + /* ------------------------------------------------------------ */ public boolean isAsyncStarted() { @@ -1788,6 +1799,16 @@ public class Request implements HttpServletRequest _scope=scope; } + /* ------------------------------------------------------------ */ + /** Set timetstamp of request dispatch + * + * @param value timestamp + */ + public void setDispatchTime(long value) + { + _dispatchTime = value; + } + /* ------------------------------------------------------------ */ public AsyncContext startAsync() throws IllegalStateException { diff --git a/jetty-server/src/main/java/org/eclipse/jetty/server/handler/RequestLogHandler.java b/jetty-server/src/main/java/org/eclipse/jetty/server/handler/RequestLogHandler.java index e2f8d6be428..1a0c26e3657 100644 --- a/jetty-server/src/main/java/org/eclipse/jetty/server/handler/RequestLogHandler.java +++ b/jetty-server/src/main/java/org/eclipse/jetty/server/handler/RequestLogHandler.java @@ -19,6 +19,7 @@ import javax.servlet.ServletException; import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletResponse; +import org.eclipse.jetty.server.AsyncContinuation; import org.eclipse.jetty.server.DispatcherType; import org.eclipse.jetty.server.Request; import org.eclipse.jetty.server.RequestLog; @@ -47,9 +48,24 @@ public class RequestLogHandler extends HandlerWrapper public void handle(String target, Request baseRequest, HttpServletRequest request, HttpServletResponse response) throws IOException, ServletException { - super.handle(target, baseRequest, request, response); - if (DispatcherType.REQUEST.equals(baseRequest.getDispatcherType()) && _requestLog!=null) - _requestLog.log((Request)request, (Response)response); + AsyncContinuation continuation = baseRequest.getAsyncContinuation(); + if (!continuation.isInitial()) + { + baseRequest.setDispatchTime(System.currentTimeMillis()); + } + + try + { + super.handle(target, baseRequest, request, response); + } + finally + { + if (_requestLog != null && DispatcherType.REQUEST.equals(baseRequest.getDispatcherType())) + { + _requestLog.log(baseRequest, (Response)response); + } + + } } /* ------------------------------------------------------------ */