如何分析 spring mvc 应用程序的页面请求

发布于 2024-09-18 01:46:18 字数 118 浏览 5 评论 0原文

在 spring mvc 应用程序中,我必须使用哪些选项来分析页面请求?

我想详细了解页面请求需要多长时间,以及各个阶段,例如渲染 freemarker 模板、hibernate 数据库调用等需要多长时间。

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.

如果你对这篇内容有疑问,欢迎到本站社区发帖提问 参与讨论,获取更多帮助,或者扫码二维码加入 Web 技术交流群。

扫码二维码加入Web技术交流群

发布评论

需要 登录 才能够评论, 你可以免费 注册 一个本站的账号。

评论(2

假装爱人 2024-09-25 01:46:19

我们刚刚使用拦截器和自定义标签完成了类似的事情。该解决方案足够“轻”,足以在生产中使用,将其数据以 HTML 注释的形式显示在响应的底部,并允许您选择使用请求参数进行更详细的日志记录。您可以将下面的拦截器应用到您想要分析的所有请求路径,并将自定义标记添加到所需页面的底部。自定义标签的位置很重要;它应该尽可能接近请求处理结束时调用,因为它只知道调用之前花费的时间(和加载的对象)。

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 会话的一级缓存统计信息,这可以揭示处理程序和视图加载了多少对象。如果不需要 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)) {
                //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;
        }
    }
}

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;
        }
    }
}
~没有更多了~
我们使用 Cookies 和其他技术来定制您的体验包括您的登录状态等。通过阅读我们的 隐私政策 了解更多相关信息。 单击 接受 或继续使用网站,即表示您同意使用 Cookies 和您的相关数据。
原文