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,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

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);

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
     {

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);
+            }
+            
+        }
     }
 
     /* ------------------------------------------------------------ */