记录第一次进入JSP慢的处理解决全过程

一、背景

前一段时间把公司后台的老项目进行了springboot升级,之前的项目是springMVC架构,确实比较老了,升级成springboot后出现个问题是第一次请求进入jsp页面特别的慢,15s-25s左右,第二次打开就快了,但是第一次进来真的太慢了,简直不能忍。

二、排查问题

2.1 排查数据库

经排查数据库响应都是毫秒级别,和数据库关系不大。
2.2 排查jsp的预编译
因为第一次进入jsp是有个jsp编译过程,但是我们框架启动服务的时候已经进行了预编译的,我怀疑是框架编译的jsp文件可能没有成功,然后我在本地通过war包启动,发现jsp页面确实被编译成了class文件,故不是这个原因引起的。
入下图所示:

2.3 网上搜索

百度谷歌一番,发现网上对于这个问题确实很对人都遇到过,但是没解决方案,有解决方案的我全部试了一遍都不行。
下面是搜索记录,确实挺无奈的,能尝试的方法都试过了还是不行

2.4 使用阿尔萨斯排查

阿里的工具arthas确实好用,排查问题的利器,我把本地把项目跑起来了,想用阿尔萨斯排查下,通过trace命令得到的线程链路如下:

[arthas@36013]$ trace com.***.controller.*** listInterview  -n 5 --skipJDKMethod false 
Press Q or Ctrl+C to abort.
Affect(class count: 2 , method count: 2) cost in 487 ms, listenerId: 1
`---ts=2021-09-17 15:54:45;thread_name=catalina-exec-28;id=94;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@63429932
    `---[171.277875ms] com.liepin.dmadmin.web.interview.core.controller.InterviewController$$EnhancerBySpringCGLIB$$42c95bb5:listInterview()
        `---[170.673417ms] org.springframework.cglib.proxy.MethodInterceptor:intercept()
            `---[164.057708ms] com.liepin.dmadmin.web.interview.core.controller.InterviewController:listInterview()
                +---[0.053334ms] java.lang.System:currentTimeMillis() #140
                +---[0.021375ms] java.lang.StringBuilder:<init>() #141
                +---[min=0.008875ms,max=0.092125ms,total=0.101ms,count=2] java.lang.StringBuilder:append() #141
                +---[5.228458ms] com.alibaba.fastjson.JSON:toJSONString() #141
                +---[0.038083ms] java.lang.StringBuilder:toString() #141
                +---[10.733625ms] com.liepin.swift.core.log.MonitorLogger:log() #141
                +---[146.26925ms] com.liepin.dmadmin.web.interview.core.biz.IInterviewBiz:listInterviewRecord() #142
                +---[0.019833ms] com.liepin.dmadmin.web.interview.core.query.InterviewQuery:setPageUrl_op() #143
                +---[0.039167ms] org.springframework.ui.Model:addAttribute() #144
                +---[0.012292ms] org.springframework.ui.Model:addAttribute() #145
                +---[0.007292ms] java.lang.StringBuilder:<init>() #146
                +---[min=0.007875ms,max=0.0265ms,total=0.034375ms,count=2] java.lang.StringBuilder:append() #146
                +---[0.008208ms] java.lang.System:currentTimeMillis() #146
                +---[0.007417ms] java.lang.StringBuilder:toString() #146
                `---[0.993958ms] com.liepin.swift.core.log.MonitorLogger:log() #146

在我本地请求jsp页面居然不到1s数据就出来了,根本看不出来到底哪里慢,这又一次让我无从下手。
2.5 定位问题
之后每天开发完需求我都会抽出一点时间排查这个问题,大概过了一个月,还是没有一点进展,项目里的一位大佬要出手解决这个问题了,他通过线程快照分析出来原因是返回到jsp页面会带有一些实体类,这些实体类因为没有被加载到jvm,然后第一次进入jsp页面又需要用到这些实体类,所以会有一些解压和加载类的过程,所以比较慢。
下面是线程信息:

<thread>
      <id>198</id>
      <name>catalina-exec-92</name>
      <state>RUNNABLE</state>
      <cpuTime>17977.7240ms</cpuTime>
      <userTime>16440.0000ms</userTime>
      <stackTrace>
        at java.util.zip.Inflater.inflateBytes(Native Method)
        at java.util.zip.Inflater.inflate(Inflater.java:259)
        at java.util.zip.InflaterInputStream.read(InflaterInputStream.java:152)
        at java.util.zip.ZipInputStream.read(ZipInputStream.java:194)
        at java.util.jar.JarInputStream.read(JarInputStream.java:207)
        at java.util.zip.ZipInputStream.closeEntry(ZipInputStream.java:140)
        at java.util.zip.ZipInputStream.getNextEntry(ZipInputStream.java:118)
        at java.util.jar.JarInputStream.getNextEntry(JarInputStream.java:142)
        at java.util.jar.JarInputStream.getNextJarEntry(JarInputStream.java:179)
        at org.apache.catalina.webresources.JarWarResourceSet.getArchiveEntries(JarWarResourceSet.java:117)
        at org.apache.catalina.webresources.AbstractArchiveResourceSet.getResource(AbstractArchiveResourceSet.java:253)
        at org.apache.catalina.webresources.StandardRoot.getResourceInternal(StandardRoot.java:281)
        at org.apache.catalina.webresources.Cache.getResource(Cache.java:62)
        at org.apache.catalina.webresources.StandardRoot.getResource(StandardRoot.java:216)
        at org.apache.catalina.webresources.StandardRoot.getClassLoaderResource(StandardRoot.java:225)
        at org.apache.catalina.loader.WebappClassLoaderBase.findClassInternal(WebappClassLoaderBase.java:2299)
        at org.apache.catalina.loader.WebappClassLoaderBase.findClass(WebappClassLoaderBase.java:863)
        at org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader.findClassIgnoringNotFound(TomcatEmbeddedWebappClassLoader.java:121)
        at org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader.doLoadClass(TomcatEmbeddedWebappClassLoader.java:86)
        at org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader.loadClass(TomcatEmbeddedWebappClassLoader.java:68)
        at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1186)
        at java.lang.Class.forName0(Native Method)
        at java.lang.Class.forName(Class.java:348)
        at com.sun.beans.finder.ClassFinder.findClass(ClassFinder.java:67)
        at com.sun.beans.finder.ClassFinder.findClass(ClassFinder.java:110)
        at java.beans.Introspector.findCustomizerClass(Introspector.java:1301)
        at java.beans.Introspector.getTargetBeanDescriptor(Introspector.java:1295)
        at java.beans.Introspector.getBeanInfo(Introspector.java:425)
        at java.beans.Introspector.getBeanInfo(Introspector.java:173)
        at javax.el.BeanELResolver$BeanProperties.<init>(BeanELResolver.java:221)
        at javax.el.BeanELResolver.property(BeanELResolver.java:343)
        at javax.el.BeanELResolver.getValue(BeanELResolver.java:92)
        at org.apache.jasper.el.JasperELResolver.getValue(JasperELResolver.java:113)
        at org.apache.el.parser.AstValue.getValue(AstValue.java:169)
        at org.apache.el.ValueExpressionImpl.getValue(ValueExpressionImpl.java:190)
        at org.apache.jasper.runtime.PageContextImpl.proprietaryEvaluate(PageContextImpl.java:701)
        at org.apache.jsp.manage.xycomp.edit_jsp._jspService(edit_jsp.java:246)

上面的流程清晰的表面了,jsp里面因为用到了实体类对象,因为没有被加载,所以需要把这些类加载到内存里去,然后会解压jar包,读流,类加载,所以比较慢。目前来看,终于定位到问题了!下一步就是要想着怎么解决了。

三、解决问题

3.1 大佬的解决方式

定位到这个问题的大佬因为需求多,就没时间解决这个问题了,另一位大佬出手来解决这个问题,他的思路是既然返回到页面是个实体类对象慢是吧,那还不好办,我不返给你jsp页面对象了,我直接返给你一个map,我让你从map里面取key取value,我就不信你还慢,大佬按照这个思路写了一个拦截器,返回页面的时候会自动把实体类转换成map,然后发布项目,一尝试,真的把问题解决了!速度嗷嗷快!

3.2 弊端

大佬这个把对象转map的曲线救国的思路的确可行,能解决问题,但是这个方式有个问题,就是原来jsp页面里的枚举全部失效了,也就是说返回的map不支持枚举,jsp页面显示有问题,这个时候需要改页面了,不能用枚举接收了,返回的map也要对应的加新字段,后端几十个页面就得花很多时间来改了。于是自己尝试换个方式解决下。

3.3 我的尝试

既然是类没有被加载,我自己写个类加载器加载到内存不就可以了,结果试了试不行。
后来我自己重新Dump一份内存快照好好分析下,内容和上面的差不多就不粘贴出来了,我发现每个调用链路都会执行这个方法: Introspector.getBeanInfo 这个方法平时开发根本用不上也没关注,然后查询了下,这个是java的内省方法,内省是干嘛的呢,简单来说,前端传参数过来,后端用@RequestBody注解接收,那么前端传的json数据怎么和后端接收的实体对应上的呢?后端接收实体中的字段都是private类型,无法直接设置字段值(反射虽然可以设置,但是并不合适),只能通过Setter方法进行设置,但是程序怎么知道JavaBean有哪些Setter方法呢?此处就用到了JavaBean的内省机制。java的内省工具Introspector的getBeanInfo方法,我们可以获取一个JavaBean的内省BeanInfo,获取到的BeanInfo包含以下属性:Bean的类相关信息、Bean的事件信息、Bean的属性信息、Bean的方法信息、额外属性信息、Component的图标。内省更多信息参考:javabean内省
由此可见,jsp页面里面也需要获取javabean的信息,但是由于bean没有被加载带jvm,所以是先要进行加载的过程,所以第一次请求过来是比较慢的,既然知道这个是罪魁祸首,那就解决你就可以了,怎么解决呢,我的方法简单粗暴,项目启动的时候,扫描jsp页面用到的bean,提前帮你内省不就可以了。

下面是核心代码

     // 解决第一次进入页面实体类慢问题
     Introspector.getBeanInfo(clazz);
     Field[] fields = ReflectUtil.getFields(clazz);
     for (Field field : fields) {
         // 解决第一次进入页面实体类里的枚举类慢问题
         if (ClassUtil.isEnum(field.getType())) {
             Introspector.getBeanInfo(field.getType());
         }
     }

耗时1个多月的jsp页面第一次请求慢的问题终于被解决!

最后修改:2021 年 10 月 03 日 08 : 06 PM