KNL-80

Patch from Stephen Marquard

The attached patch adds some debug logging to the RequestFilter to assist in the analysis of number of db queries executed per request, and elapsed time per request.

This would have no effect in production instances where debug logging for RequestFilter is not enabled.

Thanks

git-svn-id: https://source.sakaiproject.org/svn/kernel/trunk@54687 66ffb92e-73f9-0310-93c1-f5514f145a0a

kernel/api/src/main/java/org/sakaiproject/util/RequestFilter.java

@@ -504,6 +504,7 @@ public void destroy()
 	public void doFilter(ServletRequest requestObj, ServletResponse responseObj, FilterChain chain) throws IOException,
 			ServletException
 	{
+		StringBuffer sb = null;
 		long startTime = System.currentTimeMillis();
 
 		// bind some preferences as "current"
@@ -563,6 +564,20 @@ public void doFilter(ServletRequest requestObj, ServletResponse responseObj, Fil
 			// filter the request
 			else
 			{
+				if (M_log.isDebugEnabled())
+				{
+					sb = new StringBuffer("http-request: ");
+					sb.append(req.getMethod());
+					sb.append(" ");
+					sb.append(req.getRequestURL());
+					if (req.getQueryString() != null)
+					{
+						sb.append("?");
+						sb.append(req.getQueryString());
+					}
+					M_log.debug(sb);
+				}
+
 				try
 				{
 					// mark the request as filtered to avoid re-filtering it later in the request processing
@@ -628,10 +643,10 @@ public void doFilter(ServletRequest requestObj, ServletResponse responseObj, Fil
 			// delete any temp files
 			deleteTempFiles(tempFiles);
 
-			if (M_log.isDebugEnabled())
+			if (M_log.isDebugEnabled() && sb != null)
 			{
 				long elapsedTime = System.currentTimeMillis() - startTime;
-				M_log.debug("request timing (ms): " + elapsedTime);
+				M_log.debug("request timing (ms): " + elapsedTime + " for " + sb);
 			}
 		}
 	}