Spring应用程序在加载下经历全面延迟

Question

我正在Java8 (1.8.0_161-b12 / HotSpot 64 25.161-b12)上使用Thymeleaf (2.1.4)运行遗留Spring (1.4.4)应用程序。当应用程序经历中度负载(1K reqs/min)时，所有应用程序请求都会出现延迟(> 1分钟)，而应用程序实例上的CPU则会最大。

我怎样才能准确地指出这个性能瓶颈发生在哪里呢？如果这是一个代码/设计问题，我如何才能确定，或者如果我只需要分配更多的资源？

我尝试过的事情：

• 扩展DB并增加连接池大小( CPU可以忽略)
• 禁用了模板/表达式(Thymeleaf)和查询缓存(Hibernate/couchbase)，并经历了相同的延迟。

其他要注意的事项：

• JVM堆没有配置，但似乎没有达到最大堆大小。

​

• JVM监视显示在加载w/ ParallelGCFailedAllocation期间经常发生的垃圾收集(分配失败)

。

​

• 有几个Full GC事件发生，占用b/w 1-3秒。
• A在峰值延迟期间的堆转储显示超过172个阻塞线程，这些线程似乎在等待Thymeleaf缓存PUT请求？！

。

"http-nio-8080-exec-168" - Thread t@488
   java.lang.Thread.State: BLOCKED
        at org.thymeleaf.cache.StandardCache$CacheDataContainer.putWithoutTracing(StandardCache.java:384)
        - waiting to lock <4e409b1c> (a [Ljava.lang.Object;) owned by "http-nio-8080-exec-170" t@490
        at org.thymeleaf.cache.StandardCache$CacheDataContainer.put(StandardCache.java:368)
        at org.thymeleaf.cache.StandardCache.put(StandardCache.java:141)
        at org.thymeleaf.spring4.expression.SpelVariableExpressionEvaluator.getExpression(SpelVariableExpressionEvaluator.java:184)
        at org.thymeleaf.spring4.expression.SpelVariableExpressionEvaluator.evaluate(SpelVariableExpressionEvaluator.java:129)
        at org.thymeleaf.standard.expression.VariableExpression.executeVariable(VariableExpression.java:154)
        at org.thymeleaf.standard.expression.SimpleExpression.executeSimple(SimpleExpression.java:59)
        at org.thymeleaf.standard.expression.Expression.execute(Expression.java:103)
        at org.thymeleaf.standard.expression.Expression.execute(Expression.java:133)
        at org.thymeleaf.standard.expression.Expression.execute(Expression.java:120)
        at org.thymeleaf.standard.processor.attr.AbstractStandardLocalVariableDefinitionAttrProcessor.getNewLocalVariables(AbstractStandardLocalVariableDefinitionAttrProcessor.java:89)
        at org.thymeleaf.processor.attr.AbstractLocalVariableDefinitionAttrProcessor.processAttribute(AbstractLocalVariableDefinitionAttrProcessor.java:62)
        at org.thymeleaf.processor.attr.AbstractAttrProcessor.doProcess(AbstractAttrProcessor.java:87)
        at org.thymeleaf.processor.AbstractProcessor.process(AbstractProcessor.java:212)
        at org.thymeleaf.dom.Node.applyNextProcessor(Node.java:1017)
        at org.thymeleaf.dom.Node.processNode(Node.java:972)
        at org.thymeleaf.dom.NestableNode.computeNextChild(NestableNode.java:695)
        at org.thymeleaf.dom.NestableNode.doAdditionalProcess(NestableNode.java:668)
        at org.thymeleaf.dom.Node.processNode(Node.java:990)
        at org.thymeleaf.dom.NestableNode.computeNextChild(NestableNode.java:695)
        at org.thymeleaf.dom.NestableNode.doAdditionalProcess(NestableNode.java:668)
        at org.thymeleaf.dom.Node.processNode(Node.java:990)
        at org.thymeleaf.dom.NestableNode.computeNextChild(NestableNode.java:695)
        at org.thymeleaf.dom.NestableNode.doAdditionalProcess(NestableNode.java:668)
        at org.thymeleaf.dom.Node.processNode(Node.java:990)
        at org.thymeleaf.dom.NestableNode.computeNextChild(NestableNode.java:695)
        at org.thymeleaf.dom.NestableNode.doAdditionalProcess(NestableNode.java:668)
        at org.thymeleaf.dom.Node.processNode(Node.java:990)
        at org.thymeleaf.dom.NestableNode.computeNextChild(NestableNode.java:695)
        at org.thymeleaf.dom.NestableNode.doAdditionalProcess(NestableNode.java:668)
        at org.thymeleaf.dom.Node.processNode(Node.java:990)
        at org.thymeleaf.dom.Document.process(Document.java:93)
        at org.thymeleaf.TemplateEngine.process(TemplateEngine.java:1155)
        at org.thymeleaf.TemplateEngine.process(TemplateEngine.java:1060)
        at org.thymeleaf.TemplateEngine.process(TemplateEngine.java:1011)
        at org.thymeleaf.spring4.view.ThymeleafView.renderFragment(ThymeleafView.java:335)
        at org.thymeleaf.spring4.view.ThymeleafView.render(ThymeleafView.java:190)
        at org.springframework.web.servlet.DispatcherServlet.render(DispatcherServlet.java:1271)

既然应用程序有很多层，有没有办法找出罪魁祸首呢？

更新：

好的，在进一步挖掘之后，再做几件事：

在负载测试的另一个点上，

1. 显示了一堆在hibernate调用数据库时阻塞的线程。

 java.lang.Thread.State: BLOCKED
        at sun.security.provider.NativePRNG$RandomIO.implNextBytes(NativePRNG.java:543)
        - waiting to lock <3d1c45eb> (a java.lang.Object) owned by "http-nio-8080-exec-270" t@823
        at sun.security.provider.NativePRNG$RandomIO.access$400(NativePRNG.java:331)
        at sun.security.provider.NativePRNG.engineNextBytes(NativePRNG.java:220)
        at java.security.SecureRandom.nextBytes(SecureRandom.java:468)
        at sun.security.ssl.CipherBox.createExplicitNonce(CipherBox.java:1015)
        at sun.security.ssl.OutputRecord.encrypt(OutputRecord.java:248)
        at sun.security.ssl.SSLSocketImpl.writeRecordInternal(SSLSocketImpl.java:869)
        at sun.security.ssl.SSLSocketImpl.writeRecord(SSLSocketImpl.java:857)
        at sun.security.ssl.AppOutputStream.write(AppOutputStream.java:123)
        - locked <7721ca63> (a sun.security.ssl.AppOutputStream)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
        at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
        - locked <2135117a> (a java.io.BufferedOutputStream)
        at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3725)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2506)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2677)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2549)
        - locked <5c36dc6f> (a com.mysql.jdbc.JDBC4Connection)
        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861)
        - locked <5c36dc6f> (a com.mysql.jdbc.JDBC4Connection)
        at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1962)
        - locked <5c36dc6f> (a com.mysql.jdbc.JDBC4Connection)
        at sun.reflect.GeneratedMethodAccessor254.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.github.gquintana.metrics.proxy.MethodInvocation.proceed(MethodInvocation.java:75)
        at com.github.gquintana.metrics.sql.PreparedStatementProxyHandler.execute(PreparedStatementProxyHandler.java:53)
        at com.github.gquintana.metrics.sql.AbstractStatementProxyHandler.invoke(AbstractStatementProxyHandler.java:50)
        at com.github.gquintana.metrics.proxy.ProxyHandler.invoke(ProxyHandler.java:56)
        at com.sun.proxy.$Proxy143.executeQuery(Unknown Source)
        at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:79)
        at org.hibernate.loader.Loader.getResultSet(Loader.java:2062)
        at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1859)
        at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1838)
        at org.hibernate.loader.Loader.doQuery(Loader.java:906)
        at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:348)
        at org.hibernate.loader.Loader.doList(Loader.java:2550)
        at org.hibernate.loader.Loader.doList(Loader.java:2536)
        at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2366)
        at org.hibernate.loader.Loader.list(Loader.java:2361)
        at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:495)
        at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:357)
        at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:198)
        at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1230)
        at org.hibernate.internal.QueryImpl.list(QueryImpl.java:101)
        at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:268)
        at org.hibernate.ejb.criteria.CriteriaQueryCompiler$3.getResultList(CriteriaQueryCompiler.java:254)
        at org.broadleafcommerce.common.i18n.dao.TranslationDaoImpl.readTranslation(TranslationDaoImpl.java:262)
        at org.broadleafcommerce.common.i18n.service.TranslationServiceImpl.getTranslatedValue(TranslationServiceImpl.java:194)
        at org.broadleafcommerce.common.i18n.service.DynamicTranslationProvider.getValue(DynamicTranslationProvider.java:47)
        at org.broadleafcommerce.core.catalog.domain.CategoryImpl.getName(CategoryImpl.java:489)
        at org.<myorg>.CatalogService.lambda$getSeries1ActiveTechniques$11(CatalogService.java:95)

通常，这个调用getSeries1ActiveTechniques位于hibernate查询缓存的后面，但是禁用它后，对SQL数据库的流量就会大大增加。

虽然我知道这个设计需要重构，但我仍然不清楚这种减速是由于整个CPU的负载，总体GC影响CPU，还是这两个独立的争论导致GC和高CPU？

测试期间

1. CPU采样显示：

​

​

热点显示某些调用的CPU较高；跳出的是org.apache.catalina.webresources.JarWarResourceSet.getArchiveEntries，它可能是带有嵌入式tomcat的known issue？

但是，我如何知道这些CPU时间是否真正具有代表性，或者这些方法是否只是受到GC或线程池限制在apache/jdbc级别的更大的普遍减速的影响？

Answer 1

您将发现免费使用更新版本的Java将获得更好的性能，这将有助于您报告的GC延迟。如果延迟是一个问题，那么您应该考虑升级到Java 11或Java 17。

然而，您突出显示的一组锁才是真正的问题。Thymeleaf缓存看起来像是每个请求都持有一个全局锁(或者至少是高度竞争的锁)，而后面的所有内容都是序列化的。目前还不清楚您所依赖的库是否有升级(2.1.6是最新的，但也有3.x系列)；或者，它们可能有不同的缓存实现，您可以选择/配置。看起来StandardCache才是罪魁祸首；也许你可以用另一种方法呢？

您可以尝试禁用缓存，以查看是否可以删除锁，尽管拥有缓存确实是有意义的。

https://www.thymeleaf.org/doc/tutorials/2.1/usingthymeleaf.html#template-cache