how to profile a page request for a spring mvc app

what options do I have to profile a page request开发者_如何转开发 in a spring mvc app?

I want to get a breakdown of how long the page request takes, along with the various stages like how long it takes to render the freemarker template, hibernate db calls, etc.

We just accomplished something similar with an interceptor and a custom tag. This solution is "light" enough to be used in production, presents its data as HTML comments at the bottom of the response, and allows you to opt into the more verbose logging with a request parameter. You apply the interceptor below to all request paths you want to profile, and you add the custom tag to the bottom of the desired pages. The placement of the custom tag is important; it should be invoked as close to the end of request processing as possible, as it's only aware of time spent (and objects loaded) prior to its invocation.

package com.foo.web.interceptor;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

import org.springframework.web.servlet.ModelAndView;
import org.springframework.web.servlet.handler.HandlerInterceptorAdapter;

public class PageGenerationTimeInterceptor extends HandlerInterceptorAdapter {

    public static final String PAGE_START_TIME = "page_start_time";
    public static final String PAGE_GENERATION_TIME = "page_generation_time";

    public boolean preHandle(HttpServletRequest request, HttpServletResponse response,
            Object handler) throws Exception {
        request.setAttribute(PAGE_START_TIME, new Long(System.currentTimeMillis()));
        return true;
    }

    public void postHandle(HttpServletRequest request, HttpServletResponse response,
            Object handler, ModelAndView modelAndView) throws Exception {
        Long startTime = (Long) request.getAttribute(PAGE_START_TIME);
        if (startTime != null) {
            request.setAttribute(PAGE_GENERATION_TIME, new Long(System.currentTimeMillis() - startTime.longValue()));
        }
    }
}

The custom tag looks for the request attributes, and uses them to compute the handler time, the view time, and the total time. It can also query the current Hibernate session for first-level cache statistics, which can shed some light on how many objects were loaded by the handler and view. If you don't need the Hibernate information, you can delete the big if block.

package com.foo.web.taglib;

import java.io.IOException;
import java.util.HashMap;
import java.util.Map;
import java.util.SortedSet;
import java.util.TreeSet;

import javax.servlet.ServletContext;
import javax.servlet.jsp.JspException;
import javax.servlet.jsp.JspWriter;
import javax.servlet.jsp.tagext.Tag;
import javax.servlet.jsp.tagext.TryCatchFinally;

import org.apache.log4j.LogManager;
import org.apache.log4j.Logger;
import org.hibernate.Session;
import org.hibernate.SessionFactory;
import org.hibernate.engine.CollectionKey;
import org.hibernate.engine.EntityKey;
import org.hibernate.stat.SessionStatistics;
import org.springframework.beans.factory.BeanFactoryUtils;
import org.springframework.context.ApplicationContext;
import org.springframework.web.bind.ServletRequestUtils;
import org.springframework.web.context.support.WebApplicationContextUtils;
import org.springframework.web.servlet.tags.RequestContextAwareTag;

import com.foo.web.interceptor.PageGenerationTimeInterceptor;

public class PageInfoTag extends RequestContextAwareTag implements TryCatchFinally {
    private static final long serialVersionUID = -8448960221093136401L;
    private static final Logger LOGGER = LogManager.getLogger(PageInfoTag.class);
    public static final String SESSION_STATS_PARAM_NAME = "PageInfoTag.SessionStats";

    @Override
    public int doStartTagInternal() throws JspException {
        try {
            JspWriter out = pageContext.getOut();
            Long startTime = (Long)pageContext.getRequest().getAttribute(PageGenerationTimeInterceptor.PAGE_START_TIME);
            Long handlerTime = (Long)pageContext.getRequest().getAttribute(PageGenerationTimeInterceptor.PAGE_GENERATION_TIME);
            if (startTime != null && handlerTime != null) {
                long responseTime = System.currentTimeMillis() - startTime.longValue();
                long viewTime = responseTime - handlerTime;
                out.append(String.format("<!-- total: %dms, handler: %dms, view: %dms -->", responseTime, handlerTime, viewTime));
            }
            if (ServletRequestUtils.getBooleanParameter(pageContext.getRequest(), SESSION_STATS_PARAM_NAME, false)) {
                //write another long HTML comment with information about contents of Hibernate first-level cache
                ServletContext servletContext = pageContext.getServletContext();
                ApplicationContext context =  WebApplicationContextUtils.getRequiredWebApplicationContext(servletContext);
                String[] beans = BeanFactoryUtils.beanNamesForTypeIncludingAncestors(context,
                        SessionFactory.class, false, false);

                if (beans.length > 0) {
                    SessionFactory sessionFactory = (SessionFactory) context.getBean(beans[0]);
                    Session session = sessionFactory.getCurrentSession();
                    SessionStatistics stats = session.getStatistics();
                    Map<String, NamedCount> entityHistogram = new HashMap<String, NamedCount>();
                    out.append("\n<!-- session statistics:\n");
                    out.append("\tObject keys (").append(String.valueOf(stats.getEntityCount())).append("):\n");
                    for (Object obj: stats.getEntityKeys()) {
                        EntityKey key = (EntityKey)obj;
                        out.append("\t\t").append(key.getEntityName()).append("#").append(key.getIdentifier().toString()).append("\n");
                        increment(entityHistogram, key.getEntityName());
                    }
                    out.append("\tObject key histogram:\n");
                    SortedSet<NamedCount> orderedEntityHistogram = new TreeSet<NamedCount>(entityHistogram.values());
                    for (NamedCount entry: orderedEntityHistogram) {
                        out.append("\t\t").append(entry.name).append(": ").append(String.valueOf(entry.count)).append("\n");
                    }
                    Map<String, NamedCount> collectionHistogram = new HashMap<String, NamedCount>();
                    out.append("\tCollection keys (").append(String.valueOf(stats.getCollectionCount())).append("):\n");
                    for (Object obj: stats.getCollectionKeys()) {
                        CollectionKey key = (CollectionKey)obj;
                        out.append("\t\t").append(key.getRole()).append("#").append(key.getKey().toString()).append("\n");
                        increment(collectionHistogram, key.getRole());
                    }
                    out.append("\tCollection key histogram:\n");
                    SortedSet<NamedCount> orderedCollectionHistogram = new TreeSet<NamedCount>(collectionHistogram.values());
                    for (NamedCount entry: orderedCollectionHistogram) {
                        out.append("\t\t").append(entry.name).append(": ").append(String.valueOf(entry.count)).append("\n");
                    }
                    out.append("-->");
                }
            }
        } catch (IOException e) {
            LOGGER.error("Unable to write page info tag");
            throw new RuntimeException(e);
        }
        return Tag.EVAL_BODY_INCLUDE;
    }

    protected void increment(Map<String, NamedCount> histogram, String key) {
        NamedCount count = histogram.get(key);
        if (count == null) {
            count = new NamedCount(key);
            histogram.put(key, count);
        }
        count.count++;
    }

    class NamedCount implements Comparable<NamedCount>  {
        public String name;
        public int count;

        public NamedCount(String name) {
            this.name = name;
            count = 0;
        }

        @Override
        public int compareTo(NamedCount other) {
            //descending count, ascending name
            int compared = other.count - this.count;
            if (compared == 0) {
                compared = this.name.compareTo(other.name);
            }
            return compared;
        }
    }
}

Take a look here:

Profiling with Eclipse and remote profile agents on Linux

Tutorial: Profiling with TPTP and Tomcat

An introduction to profiling Java applications using TPTP

TPTP = Eclipse Test and Performance Tools Platform

More links to the stack:

Open Source Profilers in Java