java web应用程序中15% cpu使用率的检测

Question

最近，我们在我们的java web应用程序中升级了hibernate jars。在这次升级之后，我们发现cpu使用量增加了15-20%。唯一的区别是之前和之后的hibernate jar版本。我需要确定cpu使用量增加的根本原因。我拍摄了jvisualvm cpu剖析器快照，并将它们转换成火焰图。从两个火焰图中，我看到堆栈跟踪是相同的，但是cpu %是不同的。

在升级前后执行具有相同用户负载和用例的负载测试。这两个应用程序部署之间唯一的区别是hibernate jars。一个版本有hibernate 4.3.5，另一个版本有5.4.2。火焰图不精确地指出hibernate函数是cpu使用量增加的原因，因此我不知道如何继续进行分析。

我需要一些指导，如何比较两个火焰图和疑难解答的根本原因增加的cpu使用。请在这些链接中找到火焰图。

采样5分钟

火焰图前- 5min.html?t=k4t2i379

火焰图后- 5min.html?t=k4t2i379

剖析器快照- 5Minute.nps?t=fvno95sr

分析器快照后- 5Minute.nps?t=fvno95sr

采样30分钟

火焰图前- 30min.html?t=ttb7s4k4

火焰图后- 30min.html?t=ttb7s4k4

剖析器快照- 30min.nps?t=fvno95sr

分析器快照后- 30min.nps?t=fvno95sr

Answer 1

比较两个采样会话的一个好方法是比较热方法直方图。它可以在VisualVM中完成，也可以通过以下SJK命令完成。

sjk ssa --histo --by-term -f OldHibernateLibrary_30min.nps
Trc     (%)  Frm  N  Term   (%)  Frame
 64450  53%  64450   64450  53%  java.util.concurrent.LinkedBlockingQueue.poll(Unknown Source)
 22503  18%  22503   22503  18%  sun.nio.ch.SocketChannelImpl.read(Unknown Source)
  8954   7%  8954     8954   7%  sun.nio.ch.SelectorImpl.select(Unknown Source)
  6943   5%  6943     6943   5%  java.lang.ClassLoader.loadClass(Unknown Source)
  3828   3%  3828     3828   3%  java.lang.Thread.sleep(Native Method)
  1918   1%  1918     1918   1%  java.lang.Object.wait(Native Method)
  1674   1%  1674     1674   1%  sun.nio.ch.SocketChannelImpl.write(Unknown Source)
...
Trc     (%)  Frm  N  Term   (%)  Frame
 60427  44%  60427   60427  44%  java.util.concurrent.LinkedBlockingQueue.poll(Unknown Source)
 28568  21%  28568   28568  21%  java.lang.ClassLoader.loadClass(Unknown Source)
 23072  17%  23072   23072  17%  sun.nio.ch.SocketChannelImpl.read(Unknown Source)
  6181   4%  6181     6181   4%  sun.nio.ch.SelectorImpl.select(Unknown Source)
  3030   2%  3030     3030   2%  java.lang.Thread.sleep(Native Method)
  1542   1%  1542     1542   1%  sun.nio.ch.SocketChannelImpl.write(Unknown Source)
  1451   1%  1451     1451   1%  java.util.concurrent.LinkedBlockingQueue.take(Unknown Source)
...
sjk ssa --histo --by-term -f LatestHibernateLibrary_30min.nps

简单的浏览，虽然我可以发现java.lang.ClassLoader.loadClass从5%增长到21% (请注意，这是一个百分比从总样本计数，他们没有转化为CPU的使用)。

假设这两个快照都是在相同的负载下拍摄的(我无法验证VisualVM快照的形式)，我可以得出结论，java.lang.ClassLoader.loadClass是导致CPU使用率下降的罪魁祸首。

进一步滤波直方图

sjk ssa -他的

我看不出新旧版本有什么区别，e.i。不同版本之间的使用模式保持不变。

从直方图中我可以看到java.lanf.ClassLoader.loadClass的所有路径都经过org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke，所以有问题的路径在下面

java.lang.ClassLoader.loadClass(Unknown Source)
org.springframework.util.ClassUtils.isVisible(Unknown Source)
org.springframework.util.ClassUtils.getAllInterfacesForClassAsSet(Unknown Source)
org.springframework.util.ClassUtils.getAllInterfacesForClassAsSet(Unknown Source)
org.springframework.orm.jpa.ExtendedEntityManagerCreator.createProxy(Unknown Source)
org.springframework.orm.jpa.ExtendedEntityManagerCreator.createProxy(Unknown Source)
org.springframework.orm.jpa.ExtendedEntityManagerCreator.createApplicationManagedEntityManager(Unknown Source)
org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.invokeProxyMethod(Unknown Source)
org.springframework.orm.jpa.AbstractEntityManagerFactoryBean$ManagedEntityManagerFactoryInvocationHandler.invoke(Unknown Source)
com.sun.proxy.$Proxy671.createEntityManager(Unknown Source)
com.spmsoftware.appframework.persistence.MultitenantEntityManagerFactory.createEntityManager(Unknown Source)
org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(Unknown Source)

结论

VisualVM采样显示，java.lanf.ClassLoader.loadClass方法所花费的时间增加了。不幸的是，这是基于线程转储的采样限制，您不能在本机方法中进行选择。

java.lanf.ClassLoader.loadClass利用率在中是非常高的，都是一种新的方法，这就使得我在框架中出现了一些误解。

java.lanf.ClassLoader.loadClass高时很可能是线程之间争用的结果，而不是实际的CPU使用情况。虽然度量中的相对变化给了我们一个理由来考虑它与CPU使用有关，但增长的根本原因。