当前位置：首页 > article >正文

记一次 SpringBoot 静态资源加载慢的问题

article 2025/1/22 22:44:31

记一次 SpringBoot 静态资源加载慢的问题

背景
分析和定位
- 初步分析
- debug 日志打开
- 工具观测与定位
- 进一步分析
处理方式
- 关键词检索
- 方案调试
- 方案分析
复盘
- 工具复盘
- 知识体系复盘
Reference

背景

最近作一个旧的单体项目开发，碰都了有点诡异的问题，随手记录一下。
问题的排查思路和手段值得整理和复盘。
项目技术栈列一下：

JDK 1.8
Spring Boot 2.0.6.RELEASE
Spring Security 5.0.9.RELEASE
Spring Session + Redis 实现多节点Session 共享
JSP + EasyUI 后台管理项目

此问题是：
页面加载速度慢，甚至静态资源（js, css, 图片）也满，短则200多ms，长则500多ms。
在这里插入图片描述

其中的 1ms 忽略之，是谷歌浏览器的插件。

比较诡异的是：本机和测试环境都慢，但正式环境相对快一些，很多在 50~60ms。

分析和定位

初步分析

单单一个登录页面的静态资源，系统还什么都没做，加载速度就很慢。

浏览器控制台没错误，后台日志没错误，分析不到任何有价值的东西。

那怎么办，第一步打开 DEBUG日志，看看整体处理流程。

debug 日志打开

yaml 文件中把 spring boot web 的日志级别调整为 debug，进入本机 debug 运行。

logging.level.org.springframework.web: DEBUG

打开之后，就可以看到 http线程处理请求的全过程，这里列一下 JS 的处理日志：

 [2025-01-13 19:20:54,836] http-nio-7190-exec-2 DEBUG o.s.b.w.s.f.OrderedRequestContextFilter Bound request context to thread: org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper@41ff350a
[2025-01-13 19:20:54,836] http-nio-7190-exec-2 DEBUG o.s.web.servlet.DispatcherServlet DispatcherServlet with name 'dispatcherServlet' processing GET request for [/js/artDialog/artDialog.js]
[2025-01-13 19:20:54,869] http-nio-7190-exec-2 DEBUG o.s.w.s.m.m.a.RequestMappingHandlerMapping Looking up handler method for path /js/artDialog/artDialog.js
[2025-01-13 19:20:54,877] http-nio-7190-exec-2 DEBUG o.s.w.s.m.m.a.RequestMappingHandlerMapping Did not find handler method for [/js/artDialog/artDialog.js]
[2025-01-13 19:20:54,877] http-nio-7190-exec-2 DEBUG o.s.w.s.h.SimpleUrlHandlerMapping Matching patterns for request [/js/artDialog/artDialog.js] are [/js/**, /**]
[2025-01-13 19:20:54,878] http-nio-7190-exec-2 DEBUG o.s.w.s.h.SimpleUrlHandlerMapping URI Template variables for request [/js/artDialog/artDialog.js] are {}
[2025-01-13 19:20:54,878] http-nio-7190-exec-2 DEBUG o.s.w.s.h.SimpleUrlHandlerMapping Mapping [/js/artDialog/artDialog.js] to HandlerExecutionChain with handler [ResourceHttpRequestHandler [locations=[class path resource [static/js/]], resolvers=[org.springframework.web.servlet.resource.PathResourceResolver@263e6f9b]]] and 1 interceptor
[2025-01-13 19:20:54,878] http-nio-7190-exec-2 DEBUG o.s.web.servlet.DispatcherServlet Last-Modified value for [/js/artDialog/artDialog.js] is: -1
[2025-01-13 19:20:55,115] http-nio-7190-exec-2 DEBUG o.s.web.servlet.DispatcherServlet Null ModelAndView returned to DispatcherServlet with name 'dispatcherServlet': assuming HandlerAdapter completed request handling
[2025-01-13 19:20:55,115] http-nio-7190-exec-2 DEBUG o.s.web.servlet.DispatcherServlet Successfully completed request
[2025-01-13 19:20:55,115] http-nio-7190-exec-2 DEBUG o.s.b.w.s.f.OrderedRequestContextFilter Cleared thread-bound request context: org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper@41ff350a

在这里插入图片描述

浏览器请求时长为 282 ms，
在这里插入图片描述
其他的我就不列了。

SimpleUrlHandlerMapping 匹配到URI -> DispatcherServlet 处理完成这一步耗时约 273ms，问题主要在这里了。

找到了这一段的问题，怎么确定里面哪里慢呢？

都是 Spring Boot 和 Spring Security 的框架处理逻辑，怎么才能快速分析哪里耗时最长呢？
使用 Profilers 工具进行耗时分析和定位。

工具观测与定位

分析请求耗时的工具我想的有两个：Arthuas 以及 JFR。

Arthus attach 到 JVM 进程后，可以使用 trace 命令追踪请求，详细列出各步骤的耗时。

这里我是用的 IDEA 自带的 Profiler ，它可以开启 JFR Java飞行记录，将请求的耗时记录下来并解析。

View > Tool Widows > Profiler

选取对应的 JVM进程，右键 Attach IntelliJ Profiler，开启记录。
在这里插入图片描述

再去浏览器重新刷新页面，等加载完成后，回到 IDEA 的 profiler 窗口，停止Profiler。

通过控制台日志，定位本次 /js/artDialog/artDialog.js 由那个线程处理的， http-nio-7190-exec-4 号线程。
在这里插入图片描述

切回到 profiler 窗口，右上角切换到 Total Time，定位此线程：
在这里插入图片描述

在这里插入图片描述

查看右侧的火焰图，能看到 doDispatch 上面的 RedisOperationSessionRepository.save(Session) 方法耗时 558ms，占总耗时的 87.05%。
在这里插入图片描述

这里解释一下:
http-nio-7190-exe-4线程在整个追踪过程中处理了2个请求，所以这里558ms是多个请求累积的总时间，问题不大，这里是瓶颈。

我们点开 doDispatch 左边的+号，看一下调用链：

是从 SessionRepositoryFilter 的 SessionRepositoryRequestWrapper.commitSession() 方法进入的。
在这里插入图片描述

应该是 Session提交的逻辑，因为项目使用 redis 作为多节点 Session 共享的方案，所以会调用 Redis 相关的方法作一些 Session 提交保存的操作。

进入 Call Tree 调用树页面查看具体的完整调用来链：
在这里插入图片描述

明显看到，调用链在 org.springframework.session.web.http.SessionRepositoryFilter.doFilterInternal(HttpServletRequest, HttpServletResponse, FilterChain) 这里占用最多。

分成了两部分：

org.apache.catalina.core.ApplicationFilterChain.doFilter(ServletRequest, ServletResponse)
org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.access$100(SessionRepositoryFilter$SessionRepositoryRequestWrapper)

	@Override
	protected void doFilterInternal(HttpServletRequest request,
			HttpServletResponse response, FilterChain filterChain)
			throws ServletException, IOException {
		request.setAttribute(SESSION_REPOSITORY_ATTR, this.sessionRepository);

		SessionRepositoryRequestWrapper wrappedRequest = new SessionRepositoryRequestWrapper(
				request, response, this.servletContext);
		SessionRepositoryResponseWrapper wrappedResponse = new SessionRepositoryResponseWrapper(
				wrappedRequest, response);

		try {
			filterChain.doFilter(wrappedRequest, wrappedResponse);
		}
		finally {
			wrappedRequest.commitSession();
		}
	}

doFilter 中进入一系列Filter，最后进入 DispatcherServlet 的 doDispatcher 方法，查找Handler，调用 Handler.handle() 方法。

handle() 处理完成，会写内容时调用 Response write() ，因为被 SessionRepositoryFilter 包装了 Response, 所以在 flush 的时候还要 commitSession() 和 Redis 交互。

在这里插入图片描述

适合看着调用栈对照着源代码学习 Spring MVC 源码……

最后定位到 org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.commitSession(), 641 ms， SessionRepositoryRequestWrapper 是由 SessionReposirotyFilter 对 Request 的封装，入口是 SessionRepositoryFilter.doInternalFilter()。

进一步分析

redis 会慢吗？这得看比较对象了。

还记得正式环境没问题，测试环境有问题吗。

难道真的是 redis 连接延迟的问题吗？

这里列出本机 ping 测试环境 redis 和正式环境redis 的信息：
在这里插入图片描述

上面的测试环境，下面的是正式环境，慢了快10倍。

找到原因了：redis 服务器网络延迟的问题。

因为Session提交过程中，涉及到多次 redis 操作，导致耗时成倍延长，甚至静态资源都慢的要死。

处理方式

关键词检索

我们已经知道了入口逻辑在 SessionRepositoryFilter，能跳过静态资源的 Session 处理吗？

Google 搜索：spring boot SessionRepositoryFilter skip js css images static resources request

OH 果然在 GitHub 上有个 Issue，也提到了静态资源处理有 redis 操作的问题。

https://github.com/spring-projects/spring-session/issues/244

Is it possible to exclude some url from the SessionRepositoryFilter #244

跟我们的问题，完全一致：对所有静态资源依然存在 redis 大量接入操作
在这里插入图片描述

附图一张：
在这里插入图片描述

往下翻了翻，发现有人写出了 hack 代码，让静态资源跳过 SessionRepositoryFilter 的逻辑：

danielecanteri commented on Apr 24, 2017 •
Hi,
I had the same problem as above and solved adding a custom filter that marks the request as already filtered by the SessionRepositoryFilter, so that the “real” SessionRepositoryFilter won’t process the request.

@Component
@Order(Integer.MIN_VALUE)
public class ExcludeSessionRepositoryFilter extends OncePerRequestFilter {

	@Override
	protected void doFilterInternal(HttpServletRequest httpRequest, HttpServletResponse httpResponse,
			FilterChain filterChain) throws ServletException, IOException {
		if (/* here goes your logic to exclude the session repository filter, probably depending on the request uri */) {
			httpRequest.setAttribute("org.springframework.session.web.http.SessionRepositoryFilter.FILTERED", Boolean.TRUE);
		}
		filterChain.doFilter(httpRequest, httpResponse);
	}
}

I know this is somehow a dirt hack, but it works.

评论有一堆点赞的，可信度应该很高。

方案调试

最终代码逻辑如下：

@Component
@Order(Integer.MIN_VALUE)
public class ExcludeSessionRepositoryFilter extends OncePerRequestFilter {

    @Override
    protected void doFilterInternal(HttpServletRequest httpRequest, HttpServletResponse httpResponse,
                                    FilterChain filterChain) throws ServletException, IOException {
        String path = httpRequest.getRequestURI();
        // from https://github.com/spring-projects/spring-session/issues/244
        /* here goes your logic to exclude the session repository filter, probably depending on the request uri */
        if (path.startsWith("/js/") || path.startsWith("/css/") || path.startsWith("/images/")|| path.startsWith("/templates/") || path.startsWith("/favicon.ico")) {
            httpRequest.setAttribute("org.springframework.session.web.http.SessionRepositoryFilter.FILTERED", Boolean.TRUE);
        }
        filterChain.doFilter(httpRequest, httpResponse);
    }
}

我这里根据请求的URI，跳过了 js，css，images, 以及 templates, favicon.ico 的请求。

调整之后，发现请求都正常了，very 丝滑。
在这里插入图片描述

直接从 200多ms 干到 <10ms，加载速度提高了20多倍。

方案分析

SessionRepositoryFilter 继承自 OncePerRequestFilter 重写了 doFilterInternal，沿用了它的 doFilter 方法。

核心在 OncePerRequestFilter.doFilter 中：

    @Override
	public final void doFilter(ServletRequest request, ServletResponse response,
			FilterChain filterChain) throws ServletException, IOException {

		if (!(request instanceof HttpServletRequest)
				|| !(response instanceof HttpServletResponse)) {
			throw new ServletException(
					"OncePerRequestFilter just supports HTTP requests");
		}
		HttpServletRequest httpRequest = (HttpServletRequest) request;
		HttpServletResponse httpResponse = (HttpServletResponse) response;
		boolean hasAlreadyFilteredAttribute = request
				.getAttribute(this.alreadyFilteredAttributeName) != null;

		if (hasAlreadyFilteredAttribute) {

			// Proceed without invoking this filter...
			filterChain.doFilter(request, response);
		}
		else {
			// Do invoke this filter...
			request.setAttribute(this.alreadyFilteredAttributeName, Boolean.TRUE);
			try {
				doFilterInternal(httpRequest, httpResponse, filterChain);
			}
			finally {
				// Remove the "already filtered" request attribute for this request.
				request.removeAttribute(this.alreadyFilteredAttributeName);
			}
		}
	}