java - 似乎在等待的线程的高 CPU 使用率

Question

我目前正在运行一些 JMeter 测试来测试 Web 服务的性能。它使用了大量的 CPU。对于一个 JMeter 请求线程，它使用 10-30%(取决于请求类型)。当我将其增加到仅 15 个线程时，我的 CPU 利用率约为 95%。自然，我想弄清楚发生了什么。我做了一个 Hprof CPU 示例(我尝试了 times 选项，但需要一个半小时才能启动我的服务，并且没有消息会通过)。以下是该采样的结果片段(超过 15 分钟)。

CPU SAMPLES BEGIN (total = 220846) Fri Aug 22 13:38:54 2014
rank   self  accum   count trace method
   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 作者的引述的链接，其中指出:

When you have Java threads that are somehow not using the CPU, but managing to stay active, then it will appear as if those stack traces are consuming large amounts of CPU time when they aren't.

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

Answer 1

正如 Brendan Gregg 指出的您链接的博客文章，hprof 从 JVM 认为可运行的所有线程中采样。正如您在 Thread.state 的 Javadoc 中看到的，JVM 区分以下线程状态:

• NEW: A thread that has not yet started is in this state.
• RUNNABLE: A thread executing in the Java virtual machine is in this state.
• BLOCKED: A thread that is blocked waiting for a monitor lock is in this state.
• WAITING: A thread that is waiting indefinitely for another thread to perform a particular action is in this state.
• TIMED_WAITING: A thread that is waiting for another thread to perform an action for up to a specified waiting time is in this state.
• TERMINATED: A thread that has exited is in this state.

如我们所见，JVM 没有专门用于等待 I/O 的线程的状态。那是因为这样的线程实际上是被操作系统阻塞的，而不是JVM。也就是说，就 JVM 而言，等待网络适配器的线程是可运行的。实际上，RUNNABLE 状态的详细 Javadoc 写道:

Thread state for a runnable thread. A thread in the runnable state is executing in the Java virtual machine but it may be waiting for other resources from the operating system such as processor.

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

您可以:

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