How to use a filter to measure performance?

Question

I'm wondering if I can use a filter (in my case a CorsFilter) to measure timing AND to put the time taken onto the message itself. I know that the following works ok:

public void doFilter(ServletRequest request, ServletResponse response,FilterChain chain) throws IOException, ServletException {
  long startTime = System.nanoTime();
  chain.doFilter(request, response);
  long endTime = System.nanoTime();
  System.out.println("Time: " + (endTime - startTime) );
}

Which of course outputs the total time in seconds. I wanted to put the time into the header of the returned response so that the receiver could look at the header and see how long processing took. The following code doesn't work:

public void doFilter(ServletRequest request, ServletResponse response,FilterChain chain) throws IOException, ServletException {
  long startTime = System.nanoTime();
  if(response instanceof HttpServletResponse) {
    HttpServletResponse httpResp = (HttpServletResponse)response;
    httpResp.addHeader("Start-time", Long.toString(startTime));
  }

  chain.doFilter(request, response);
  long endTime = System.nanoTime();
  if(response instanceof HttpServletResponse) {
    HttpServletResponse httpResp = (HttpServletResponse)response;
    httpResp.addHeader("End-time", Long.toString(endTime));
  }
}

The header only includes Start-time and not End-time. I'm assuming that this is because the message has already been sent so modifying the object will have no effect.

Does anyone have an elegant / clever solution to put timings into the header through the use of a filter?

Thanks, Phil

Update

I've investigated the use of a HttpServletResponseWrapper to address this solution. This still fails to output either XXX-EndTime or YYY-EndTime on the response header.

@Override
public void doFilter(ServletRequest request, ServletResponse response,FilterChain chain) throws IOException, ServletException {
  long startTime = System.nanoTime();

  if(response instanceof HttpServletResponse) {
    HttpServletResponse httpResp = (HttpServletResponse)response;
    httpResp.addHeader("Access-Control-Allow-Origin", "*");
    httpResp.addHeader("Access-Control-Allow-Methods", "GET, HEAD, OPTIONS");
    httpResp.addHeader("Allow", "GET, HEAD, OPTIONS");
    httpResp.addHeader("Access-Control-Allow-Headers", "*");
    httpResp.addHeader("A-Runtime", Long.toString(startTime));
  }

  OutputStream out = response.getOutputStream();

  GenericResponseWrapper wrapper = new GenericResponseWrapper((HttpServletResponse) response);

  chain.doFilter(request,wrapper);

  out.write(wrapper.getData());

  if(response instanceof HttpServletResponse) {
HttpServletResponse httpResp = (HttpServletResponse)response;
httpResp.addHeader("XXX-EndTime", Long.toString(System.nanoTime() - startTime));

    wrapper.addHeader("YYY-EndTime", Long.toString(System.nanoTime() - startTime));
  }

  out.close();
}

Answer 1

Take a look at HttpServletResponseWrapper.

---

Okay, then code:

This code buffers the output (in two fashions) so adding the header after the pseudo-output works. Actually addHeader could have been implemented by outputting, so we are lucky it works. Border-case code. If unlucky, addHeader would have to be overriden.

Mind, when I tried, only getOutputStream was called in my test app. There is a choice to be made either electing getPrintWriter or getOutputStream.

private static class PostponingResponseWrapper extends HttpServletResponseWrapper {

    private ByteArrayOutputStream bos;
    private ServletOutputStream outputStream;
    private StringWriter sw;
    private PrintWriter printWriter;
    private boolean usingOutputStream;
    private boolean usingWriter;

    public PostponingResponseWrapper (HttpServletResponse response) {
        super(response);
        bos = new ByteArrayOutputStream();
        outputStream = new ServletOutputStream() {
            @Override
            public void write(int b) throws IOException {
                bos.write(b);
            }
        };
        sw = new StringWriter();
        printWriter = new PrintWriter(sw);
    }

    @Override
    public PrintWriter getWriter() throws IOException {
        usingWriter = true;
        LOGGER.info("getWriter usingWriter {}, usingOutputStream {}", usingWriter, usingOutputStream);
        return printWriter;
    }

    @Override
    public void flushBuffer() throws IOException {
        LOGGER.info("flushBuffer");
    }

    @Override
    public ServletOutputStream getOutputStream() throws IOException {
        usingOutputStream = true;
        LOGGER.info("getOutputStream usingWriter {}, usingOutputStream {}", usingWriter, usingOutputStream);
        ServletOutputStream out = new ServletOutputStream() {
            @Override
            public void write(int b) throws IOException {
                outputStream.write(b);
            }
        };
        return out;
    }

    public void finish() throws IOException {
        LOGGER.info("finish");
        if (usingWriter) {
            super.getWriter().print(sw.toString());
        } else if (usingOutputStream) {
            super.getOutputStream().write(bos.toByteArray());
        }
    }
}

public void doFilter(ServletRequest request, ServletResponse response,
        FilterChain chain) throws IOException, ServletException {
    HttpServletResponse httpServletResponse = (HttpServletResponse) response;
    PostponingResponseWrapper responseWrapper =
            new PostponingResponseWrapper (httpServletResponse);
    responseWrapper.addHeader("Before", "Already-Worked");
    chain.doFilter(request, responseWrapper);
    responseWrapper.addHeader("After", "And-Now-This");
    responseWrapper.finish(); // Writes the actual response
}