记一次CPU中sys消耗过高实践

达芬奇密码2018-07-19 09:55

最近在测试过程中,遇到每次的轮次中的服务器的cpu使用都超高,细看一下,原来是cpu中是sys使用率过高。详见下图,可以看到图中sys已经达到了50%以上,而usr40%左右:


一般来说,sys表示内核态的cpu使用,以下的情况中sys消耗高是可以接受的:

1.       如果cpu是满载的,诸如下面这样的配比:

user time65%~70%system time30%~35%idle time0%~5%

2.       上下文切换的数量和CPU负载直接相关。如果CPU的负载一直保持在之前可接受的平衡范围内,那么数目特别大的上下文切换是可接受的;

 

踩坑经历:

1.       根据上面的两个可以接受的情况,查看usr的使用明显要小于sys的使用;

2.       查看上下文切换以及终端的数量,并不算特别大

3.       使用远程jprofile抓取,99.8%cpu消耗都在com.caucho.util.ThreadPool.run上面,其中后面浅红色的部分,即箭头所指的部分是这个方法自身消耗的cpu,这其中只有19.9%的是消耗在login2/pwdlogin上了:


4.       服务器上抓取堆栈,waitting的都在com.caucho.util.ThreadPool.run上面

  

甚至还有BLOCKED的线程:

"resin-tcp-connection-*:36901-17" - Thread t@104438
   java.lang.Thread.State: BLOCKED
	at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:406)
	- waiting to lock <472ac1c6> (a java.net.SocksSocketImpl) owned by "resin-tcp-connection-*:36901-217" t@96886
	at java.net.ServerSocket.implAccept(ServerSocket.java:462)
	at java.net.ServerSocket.accept(ServerSocket.java:430)
	at com.caucho.vfs.QServerSocketWrapper.accept(QServerSocketWrapper.java:97)
	at com.caucho.server.port.Port.accept(Port.java:813)
	at com.caucho.server.port.TcpConnection.run(TcpConnection.java:495)
	at com.caucho.util.ThreadPool.runTasks(ThreadPool.java:527)
	at com.caucho.util.ThreadPool.run(ThreadPool.java:449)
	at java.lang.Thread.run(Thread.java:662)

   Locked ownable synchronizers:
	- None

在仔细查看这个“waiting to lock <472ac1c6>”,是被下面这个线程给锁住了:

"resin-tcp-connection-*:36901-217" - Thread t@96886
   java.lang.Thread.State: RUNNABLE
	at java.net.PlainSocketImpl.socketAccept(Native Method)
	at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:408)
	- locked <472ac1c6> (a java.net.SocksSocketImpl)
	at java.net.ServerSocket.implAccept(ServerSocket.java:462)
	at java.net.ServerSocket.accept(ServerSocket.java:430)
	at com.caucho.vfs.QServerSocketWrapper.accept(QServerSocketWrapper.java:97)
	at com.caucho.server.port.Port.accept(Port.java:813)
	at com.caucho.server.port.TcpConnection.run(TcpConnection.java:495)
	at com.caucho.util.ThreadPool.runTasks(ThreadPool.java:527)
	at com.caucho.util.ThreadPool.run(ThreadPool.java:449)
	at java.lang.Thread.run(Thread.java:662)

   Locked ownable synchronizers:
	- None

5.       查看resin.jar包的com.caucho.util.ThreadPool.run

public void run()
    {
      ClassLoader systemLoader = ClassLoader.getSystemClassLoader();

      Thread.currentThread().setContextClassLoader(systemLoader);
      try
      {
        for (int i = 0; i < ThreadPool._minSpareThreads; i++)
          startConnection(0L);
      } catch (Throwable e) {
        e.printStackTrace();
      }
      while (true)
        try
        {
          startConnection(10000L);

          Thread.currentThread(); Thread.yield();

          continue;
        }
        catch (OutOfMemoryError e)
        {
          System.exit(10);

          continue;
        }
        catch (Throwable e)
        {
          e.printStackTrace();
        }
    }

6.       从以上几个步骤可以看出,是并发的线程数过高,resin已经处理不过来了。

解决方案:

1.       增加resin部署的机器个数

2.       减少测试过程中的并发数

总结:虽然这次踩坑的现象看起来很简单,最后解决的思路也比较简单。但在问题解决的过程中可以学习到很多东西。所以以后在测试过程中遇到问题后,还是通过现象看本质,才能顺利解决问题。

本文来自网易实践者社区,经作者齐红方授权发布。