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

Question

我目前正在运行一些JMeter测试来测试Web服务的性能.它使用了非常高的CPU.对于一个JMeter请求线程,它使用10-30%的任何位置(取决于请求的类型).当我将其提升到仅仅15个线程时,我获得了~95%的CPU利用率.当然,我想知道发生了什么.我做了一个Hprof CPU示例(我尝试了时间选项但是花了一个半小时来启动我的服务并且没有消息会通过).以下是该抽样结果的片段(跨度超过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这可能会让我觉得这个结果有误导性,但我的"顶级-H"结果显示最大CPU使用率,Zabbix监控也是如此.因此,它似乎实际上消耗了CPU.但是,有一个链接来自hprof作者的引用,其中指出:

如果您的Java线程以某种方式不使用CPU,但仍然保持活动状态,则看起来好像这些堆栈跟踪消耗了大量的CPU时间.

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

Answer 1

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

• 新:尚未启动的线程处于此状态.
• RUNNABLE:在Java虚拟机中执行的线程处于此状态.
• BLOCKED:阻塞等待监视器锁定的线程处于此状态.
• WAITING:正在等待另一个线程执行特定操作的线程处于此状态.
• TIMED_WAITING:正在等待另一个线程执行最多指定等待时间的操作的线程处于此状态.
• TERMINATED:已退出的线程处于此状态.

我们可以看到,JVM没有一个等待I/O的线程的专用状态.那是因为这样的线程实际上是被操作系统阻止的,而不是JVM.也就是说,就JVM而言,等待网络适配器的线程是可运行的.实际上,RUNNABLE状态的详细Javadoc写道:

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

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

你可以:

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