We just achieved something similar with an interceptor and a custom tag. This solution is "easy" enough for use in production, presents its data as HTML comments at the bottom of the response, and allows you to choose more detailed logging with the query parameter. You apply the interceptor below to all request paths that you want to profile, and add your own tag to the bottom of the pages you need. Custom tag placement is important; it should be called as close as possible to the completion of the request, since it only knows the time spent (and the loaded objects) before it was called.
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()));
}
}
}
, . Hibernate , , . , if.
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)) {
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) {
int compared = other.count - this.count;
if (compared == 0) {
compared = this.name.compareTo(other.name);
}
return compared;
}
}
}