Commit 8ac22fc2 authored by Madhura Bhave's avatar Madhura Bhave

Add elapsed time to the Trace Actuator output

Closes gh-8654
parent 84dea526
...@@ -43,6 +43,7 @@ public class TraceProperties { ...@@ -43,6 +43,7 @@ public class TraceProperties {
defaultIncludes.add(Include.RESPONSE_HEADERS); defaultIncludes.add(Include.RESPONSE_HEADERS);
defaultIncludes.add(Include.COOKIES); defaultIncludes.add(Include.COOKIES);
defaultIncludes.add(Include.ERRORS); defaultIncludes.add(Include.ERRORS);
defaultIncludes.add(Include.TIME_TAKEN);
DEFAULT_INCLUDES = Collections.unmodifiableSet(defaultIncludes); DEFAULT_INCLUDES = Collections.unmodifiableSet(defaultIncludes);
} }
...@@ -140,6 +141,11 @@ public class TraceProperties { ...@@ -140,6 +141,11 @@ public class TraceProperties {
*/ */
REMOTE_USER, REMOTE_USER,
/**
* Include the time taken to service the request.
*/
TIME_TAKEN
} }
} }
...@@ -97,10 +97,13 @@ public class WebRequestTraceFilter extends OncePerRequestFilter implements Order ...@@ -97,10 +97,13 @@ public class WebRequestTraceFilter extends OncePerRequestFilter implements Order
this.order = order; this.order = order;
} }
@Override @Override
protected void doFilterInternal(HttpServletRequest request, protected void doFilterInternal(HttpServletRequest request,
HttpServletResponse response, FilterChain filterChain) HttpServletResponse response, FilterChain filterChain)
throws ServletException, IOException { throws ServletException, IOException {
long startTime = System.currentTimeMillis();
Map<String, Object> trace = getTrace(request); Map<String, Object> trace = getTrace(request);
logTrace(request, trace); logTrace(request, trace);
int status = HttpStatus.INTERNAL_SERVER_ERROR.value(); int status = HttpStatus.INTERNAL_SERVER_ERROR.value();
...@@ -109,6 +112,8 @@ public class WebRequestTraceFilter extends OncePerRequestFilter implements Order ...@@ -109,6 +112,8 @@ public class WebRequestTraceFilter extends OncePerRequestFilter implements Order
status = response.getStatus(); status = response.getStatus();
} }
finally { finally {
long endTime = System.currentTimeMillis();
addTimeTaken(startTime, endTime, trace);
enhanceTrace(trace, status == response.getStatus() ? response enhanceTrace(trace, status == response.getStatus() ? response
: new CustomStatusResponseWrapper(response, status)); : new CustomStatusResponseWrapper(response, status));
this.repository.add(trace); this.repository.add(trace);
...@@ -195,6 +200,11 @@ public class WebRequestTraceFilter extends OncePerRequestFilter implements Order ...@@ -195,6 +200,11 @@ public class WebRequestTraceFilter extends OncePerRequestFilter implements Order
protected void postProcessRequestHeaders(Map<String, Object> headers) { protected void postProcessRequestHeaders(Map<String, Object> headers) {
} }
private void addTimeTaken(long startTime, long endTime, Map<String, Object> trace) {
long timeTaken = endTime - startTime;
add(trace, Include.TIME_TAKEN, "timeTaken", "" + timeTaken);
}
@SuppressWarnings("unchecked") @SuppressWarnings("unchecked")
protected void enhanceTrace(Map<String, Object> trace, HttpServletResponse response) { protected void enhanceTrace(Map<String, Object> trace, HttpServletResponse response) {
if (isIncluded(Include.RESPONSE_HEADERS)) { if (isIncluded(Include.RESPONSE_HEADERS)) {
......
...@@ -33,6 +33,7 @@ import org.junit.Test; ...@@ -33,6 +33,7 @@ import org.junit.Test;
import org.springframework.boot.actuate.trace.TraceProperties.Include; import org.springframework.boot.actuate.trace.TraceProperties.Include;
import org.springframework.boot.autoconfigure.web.DefaultErrorAttributes; import org.springframework.boot.autoconfigure.web.DefaultErrorAttributes;
import org.springframework.mock.web.MockFilterChain;
import org.springframework.mock.web.MockHttpServletRequest; import org.springframework.mock.web.MockHttpServletRequest;
import org.springframework.mock.web.MockHttpServletResponse; import org.springframework.mock.web.MockHttpServletResponse;
...@@ -242,6 +243,18 @@ public class WebRequestTraceFilterTests { ...@@ -242,6 +243,18 @@ public class WebRequestTraceFilterTests {
assertThat(map.get("status").toString()).isEqualTo("404"); assertThat(map.get("status").toString()).isEqualTo("404");
} }
@Test
@SuppressWarnings("unchecked")
public void filterAddsTimeTaken() throws Exception {
MockHttpServletRequest request = spy(new MockHttpServletRequest("GET", "/foo"));
MockHttpServletResponse response = new MockHttpServletResponse();
MockFilterChain chain = new MockFilterChain();
this.filter.doFilter(request, response, chain);
String timeTaken = (String) this.repository.findAll()
.iterator().next().getInfo().get("timeTaken");
assertThat(timeTaken).isNotNull();
}
@Test @Test
public void filterHasError() { public void filterHasError() {
this.filter.setErrorAttributes(new DefaultErrorAttributes()); this.filter.setErrorAttributes(new DefaultErrorAttributes());
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment