高CPU利用率，似乎在等待的线程

Question

高CPU利用率，似乎在等待的线程

javamultithreadingperformancejmetercpu-usage

7

我目前正在运行一些JMeter测试，以测试Web服务的性能。它使用了非常高的CPU。对于一个JMeter请求线程，它使用的CPU占比在10-30％之间（取决于请求类型）。当我将它提升到仅有15个线程时，我获得了约95％的CPU利用率。自然地，我想弄清楚发生了什么。我进行了Hprof CPU采样（我尝试了times选项，但启动我的服务需要一个半小时，而且没有消息会通过）。以下是该采样结果的片段（在15分钟内）。

CPU样本开始（总数= 220846）2014年8月22日星期五13:38:54 排名自身累计计数跟踪方法 1 14.96％ 14.96％ 33038 300514 java.net.PlainSocketImpl.socketAccept 2 14.84％ 29.80％ 32776 301258 sun.nio.ch.EPollArrayWrapper.epollWait 3 12.45％ 42.26％ 27505 313002 sun.nio.ch.EPollArrayWrapper.epollWait 4 7.48％ 49.73％ 16517 300604 java.net.PlainSocketImpl.socketAccept 5 7.18％ 56.91％ 15856 303203 sun.nio.ch.EPollArrayWrapper.epollWait 6 6.18％ 63.09％ 13639 313001 sun.nio.ch.ServerSocketChannelImpl.accept0 7 6.04％ 69.13％ 13329 304259 sun.nio.ch.EPoll.epollWait 8 5.11％ 74.23％ 11275 307102 sun.nio.ch.EPollArrayWrapper.epollWait

对于这些顶部样本的相应堆栈：

TRACE 300514:
    java.net.PlainSocketImpl.socketAccept(:Unknown line)
    java.net.AbstractPlainSocketImpl.accept(:Unknown line)
    java.net.ServerSocket.implAccept(:Unknown line)
    java.net.ServerSocket.accept(:Unknown line)
    sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(:Unknown line)
    sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(:Unknown line)
    java.lang.Thread.run(:Unknown line)
TRACE 301258:
    sun.nio.ch.EPollArrayWrapper.epollWait(:Unknown line)
    sun.nio.ch.EPollArrayWrapper.poll(:Unknown line)
    sun.nio.ch.EPollSelectorImpl.doSelect(:Unknown line)
    sun.nio.ch.SelectorImpl.lockAndDoSelect(:Unknown line)
    sun.nio.ch.SelectorImpl.select(:Unknown line)
    org.apache.tomcat.util.net.NioBlockingSelector$BlockPoller.run(NioBlockingSelector.java:327)
TRACE 313002:
    sun.nio.ch.EPollArrayWrapper.epollWait(:Unknown line)
    sun.nio.ch.EPollArrayWrapper.poll(:Unknown line)
    sun.nio.ch.EPollSelectorImpl.doSelect(:Unknown line)
    sun.nio.ch.SelectorImpl.lockAndDoSelect(:Unknown line)
    sun.nio.ch.SelectorImpl.select(:Unknown line)
    org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1163)
    java.lang.Thread.run(:Unknown line)
TRACE 300604:
    java.net.PlainSocketImpl.socketAccept(:Unknown line)
    java.net.AbstractPlainSocketImpl.accept(:Unknown line)
    java.net.ServerSocket.implAccept(:Unknown line)
    java.net.ServerSocket.accept(:Unknown line)
    sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(:Unknown line)
    sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(:Unknown line)
    sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(:Unknown line)
    java.lang.Thread.run(:Unknown line)
TRACE 303203:
    sun.nio.ch.EPollArrayWrapper.epollWait(:Unknown line)
    sun.nio.ch.EPollArrayWrapper.poll(:Unknown line)
    sun.nio.ch.EPollSelectorImpl.doSelect(:Unknown line)
    sun.nio.ch.SelectorImpl.lockAndDoSelect(:Unknown line)
    sun.nio.ch.SelectorImpl.select(:Unknown line)
    net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:217)
    net.spy.memcached.MemcachedConnection.run(MemcachedConnection.java:836)
TRACE 313001:
    sun.nio.ch.ServerSocketChannelImpl.accept0(:Unknown line)
    sun.nio.ch.ServerSocketChannelImpl.accept(:Unknown line)
    org.apache.tomcat.util.net.NioEndpoint$Acceptor.run(NioEndpoint.java:793)
    java.lang.Thread.run(:Unknown line)
TRACE 304259:
    sun.nio.ch.EPoll.epollWait(:Unknown line)
    sun.nio.ch.EPollPort$EventHandlerTask.poll(:Unknown line)
    sun.nio.ch.EPollPort$EventHandlerTask.run(:Unknown line)
    java.lang.Thread.run(:Unknown line)
TRACE 307102:
    sun.nio.ch.EPollArrayWrapper.epollWait(:Unknown line)
    sun.nio.ch.EPollArrayWrapper.poll(:Unknown line)
    sun.nio.ch.EPollSelectorImpl.doSelect(:Unknown line)
    sun.nio.ch.SelectorImpl.lockAndDoSelect(:Unknown line)
    sun.nio.ch.SelectorImpl.select(:Unknown line)
    net.spy.memcached.MemcachedConnection.handleIO(MemcachedConnection.java:217)
    net.spy.memcached.MemcachedConnection.run(MemcachedConnection.java:836)

如您所见，超过一半的CPU使用率似乎来自应该在等待的线程。这不应该占用CPU时间，对吗？

我看到了这个帖子http://www.brendangregg.com/blog/2014-06-09/java-cpu-sampling-using-hprof.html，它让我想到这个结果可能是误导性的，但我的“top -H”结果显示最大的CPU使用率，Zabbix监控也是如此。因此，它实际上正在消耗CPU。然而，那里有一个链接引用了hprof作者的一句话：

当您有Java线程没有使用CPU，但设法保持活动状态时，当它们没有使用CPU时，它们的堆栈跟踪将似乎消耗大量的CPU时间。

有人能解释一下为什么会出现这种情况以及在这些情况下我可以做些什么来减少CPU使用率吗？或者所有CPU使用率指标都是误导性的吗？如果是这样，了解服务的真正CPU利用率的更好方法是什么？

- AHungerArtist

我应该注意到，随着线程数量的增加，我的请求响应时间也会增加。然而，在我的业务代码中花费的时间增加得比整个请求时间慢得多——因此，似乎随着我使用更多的线程，花费在我的业务代码中的时间比例会变得更小。这才是真正令人困扰的问题，因为我不确定如何解决这个问题。 - AHungerArtist

当我在C网络编程代码中看到这个时，通常是因为轮询超时时间太短或代码未处理它正在被通知的条件（例如错误），导致其再次被通知。 - Zan Lynx

你尝试过在非GUI模式下运行JMeter并查看是否出现相同的行为吗？ - Kevin Rave

@KevinRave 我不确定为什么这很重要。CPU结果来自服务框。我在另一个框上运行JMeter。 - AHungerArtist

嗯，也许我误读了你的帖子。虽然有点天真，但你远程调试了你的服务吗？ - Kevin Rave

1个回答

网页内容由stack overflow 提供, 点击上面的

可以查看英文原文，
原文链接

- meriton · Accepted Answer

正如Brendan Gregg在你提供的博客文章中指出的，hprof会从JVM认为可运行的所有线程中取样。如Thread.state的Javadoc所示，JVM区分以下线程状态：

NEW：尚未启动的线程处于此状态。

RUNNABLE：在Java虚拟机中执行的线程处于此状态。

BLOCKED：等待监视器锁定的线程处于此状态。

WAITING：无限期等待另一个线程执行特定操作的线程处于此状态。

TIMED_WAITING：等待另一个线程执行操作的线程最多达到指定的等待时间，该线程处于此状态。

TERMINATED：已退出的线程处于此状态。

因此，我们可以看到，JVM没有专门为等待I/O的线程设置状态。这是因为此类线程实际上是由操作系统而不是JVM阻塞的。也就是说，就JVM而言，等待网络适配器的线程是可运行的。事实上，RUNNABLE状态的详细Javadoc写道：

正在运行的线程的线程状态。处于可运行状态的线程正在Java虚拟机中执行，但它可能正在等待来自操作系统的其他资源，例如处理器。

因此，出现在hprof“cpu”采样中的I/O方法并不意味着这些方法消耗了CPU，因为它们的等待时间也被计算在内。

你可以选择：

假设I/O方法不负责CPU消耗，并关注其他方法
使用更好的分析工具，考虑等待操作系统级资源