I am writing a web Rest web service using Spring Boot.
I want to log time taken by my webservice to process request. Also I want to log headers,method and URI called.
I have done similar in my jersey web service few months back using ContainerRequestFilter and ContainerResponseFilter filter() method.
Also, AOP is Better or Filter?
Have you tried with a basic filter like this?
import java.io.IOException; import javax.servlet.*; import javax.servlet.annotation.WebFilter; import javax.servlet.http.HttpServletRequest; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.stereotype.Component; @Component @WebFilter("/*") public class StatsFilter implements Filter { private static final Logger LOGGER = LoggerFactory.getLogger(StatsFilter.class); @Override public void init(FilterConfig filterConfig) throws ServletException { // empty } @Override public void doFilter(ServletRequest req, ServletResponse resp, FilterChain chain) throws IOException, ServletException { long time = System.currentTimeMillis(); try { chain.doFilter(req, resp); } finally { time = System.currentTimeMillis() - time; LOGGER.trace("{}: {} ms ", ((HttpServletRequest) req).getRequestURI(), time); } } @Override public void destroy() { // empty } } EDITED: (Thanks @suren-aznauryan) Now, It uses Instant and Duration and avoids System.currentTimeMillis().
import java.io.IOException; import java.time.Duration; import java.time.Instant; import javax.servlet.*; import javax.servlet.annotation.WebFilter; import javax.servlet.http.HttpServletRequest; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.stereotype.Component; @Component @WebFilter("/*") public class StatsFilter implements Filter { private static final Logger LOGGER = LoggerFactory.getLogger(StatsFilter.class); @Override public void init(FilterConfig filterConfig) throws ServletException { // empty } @Override public void doFilter(ServletRequest req, ServletResponse resp, FilterChain chain) throws IOException, ServletException { Instant start = Instant.now(); try { chain.doFilter(req, resp); } finally { Instant finish = Instant.now(); long time = Duration.between(start, finish).toMillis(); LOGGER.trace("{}: {} ms ", ((HttpServletRequest) req).getRequestURI(), time); } } @Override public void destroy() { // empty } } 
@Order(Ordered.HIGHEST_PRECEDENCE) docs.spring.io/spring-framework/docs/current/javadoc-api/org/…
System.currentTimeMillis() is not a safe way to measure the elapsed time(see this post )Spring boot :logging interceptor
public class ApiLogger extends HandlerInterceptorAdapter { private static final Logger logger = LoggerFactory .getLogger(ApiLogger.class); @Override public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception { String requestId = UUID.randomUUID().toString(); log(request,response, requestId); long startTime = System.currentTimeMillis(); request.setAttribute("startTime", startTime); request.setAttribute("requestId", requestId); return true; } @Override public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception { super.afterCompletion(request, response, handler, ex); long startTime = (Long)request.getAttribute("startTime"); long endTime = System.currentTimeMillis(); long executeTime = endTime - startTime; logger.info("requestId {}, Handle :{} , request take time: {}",request.getAttribute("requestId"), handler, executeTime); } private void log(HttpServletRequest request, HttpServletResponse response, String requestId) { logger.info("requestId {}, host {} HttpMethod: {}, URI : {}",requestId, request.getHeader("host"), request.getMethod(), request.getRequestURI() ); } } register interceptor :
@Configuration @EnableWebMvc public class AppConfig extends WebMvcConfigurerAdapter { @Override public void addInterceptors(InterceptorRegistry registry) { registry.addInterceptor(new ApiLogger()).addPathPatterns("/api/v1/*"); } } 
"/api/v1/**"
If your controller is Async use Aspect to get the correct and complete execution time.
import org.aspectj.lang.ProceedingJoinPoint; import org.aspectj.lang.annotation.Around; import org.aspectj.lang.annotation.Aspect; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.stereotype.Component; import org.springframework.web.context.request.RequestContextHolder; import org.springframework.web.context.request.ServletRequestAttributes; import javax.servlet.http.HttpServletRequest; import java.util.Arrays; import java.util.UUID; @Aspect @Component public class LoggingAspect { static Logger log = LoggerFactory.getLogger(LoggingAspect.class); @Around("execution(* com.aakchoo.api.controller..*(..))") public Object profileExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable { long start = System.currentTimeMillis(); String className = joinPoint.getSignature().getDeclaringTypeName(); String methodName = joinPoint.getSignature().getName(); String apiName = className + "."+ methodName; HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getRequest(); String requestId = UUID.randomUUID().toString(); log.info("----->>>>>\nREQUESTED_ID: {}\nHOST: {} HttpMethod: {}\nURI: {}\nAPI: {}\nArguments: {}\n", requestId, request.getHeader("host"), request.getMethod(), request.getRequestURI(), apiName, Arrays.toString(joinPoint.getArgs())); Object result = joinPoint.proceed(); long elapsedTime = System.currentTimeMillis() - start; log.info("<<<<<-----\nExecution Time: {} ms [REQUESTED_ID: {}] [API: {}]", elapsedTime,requestId,apiName); return result; } } Add @EnableAspectJAutoProxy to your Applciation Class
@EnableAsync @SpringBootApplication @EnableAspectJAutoProxy public class Application { public static void main(String[] args) { SpringApplication.run(Application.class, args); } } And your build.gradle will need the following
compile 'org.aspectj:aspectjweaver:1.8.10' compile 'org.springframework.boot:spring-boot-starter-aop' 
joinPoint.proceed() throws an exception?Answer by David is correct - filter is a good way to implement such functionality in Spring Boot.
Spring Boot has a built-in endpoint which returns the information about last 100 requests like shown below:
[{ "timestamp": 1394343677415, "info": { "method": "GET", "path": "/trace", "headers": { "request": { "Accept": "text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8", "Connection": "keep-alive", "Accept-Encoding": "gzip, deflate", "User-Agent": "Mozilla/5.0 Gecko/Firefox", "Accept-Language": "en-US,en;q=0.5", "Cookie": "_ga=GA1.1.827067509.1390890128; ..." "Authorization": "Basic ...", "Host": "localhost:8080" }, "response": { "Strict-Transport-Security": "max-age=31536000 ; includeSubDomains", "X-Application-Context": "application:8080", "Content-Type": "application/json;charset=UTF-8", "status": "200" } } } },{ "timestamp": 1394343684465, ... }] If your application is calling another services or querying the database consider using Sniffy for profiling - it will show you not only time spent on your server but also time spent in calling downstream systems. See a live demo here (Check the black widget in top bottom corner).
Disclaimer: I'm the author of Sniffy
we can make use of Springboot InMemoryHttpTraceRepository by overriding add() method
public class MyCustomTraceRepository extends InMemoryHttpTraceRepository { @Override public void add(HttpTrace trace) { log(trace); super.add(trace); } //Log only you interested in public void log(HttpTrace trace) { Map<String, Object> traceMap = new LinkedHashMap<>(); traceMap.put("status", trace.getResponse().getStatus()); traceMap.put("method", trace.getRequest().getMethod()); traceMap.put("uri", trace.getRequest().getUri().getPath()); traceMap.put("timeTaken", trace.getTimeTaken()); logger.info(traceMap) } } //will Result into {status=<>, method=<>, uri=/<>, timeTaken=<>} @See more request and response trace options: https://docs.spring.io/spring-boot/docs/current/actuator-api/html/#http-trace
spring-boot-actuatorand it will already be logged for you.