java程序启动时cpu和负载高探索

简介：

这两天协助运维定位1个监控程序CPU占用率达到150%的问题，过程曲折，结论简单，很有意思：）

首先我们来看一下cpu高时候截图：

可以看到红色框中的监控程序CPU占用率都很高，但其实这些监控程序的实现很简单：发送1个http请求，收到响应后简单判断一下响应码，然后打印监控结果，打印完成就退出了。每次监控都会重新由daemon程序拉起运行。

这么简单的业务占用这么高的cpu，怎么感觉都不太可能，于是拿到监控程序的源码开始定位。

第一个想到的是VisualVm、JConsole等工具，但由于程序很快就运行完成了，这两个工具都还没有连接上就结束了，而且拿到的数据也没法看出具体是什么原因导致cpu高，尝试了一下就放弃了。

第二个尝试是用strace去跟踪程序的调用，结果摘录如下（省略很多）：

17572 14:08:43.552199 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9949000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.562857 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.563029 clock_gettime(CLOCK_REALTIME, {1423721323, 563056000}) = 0
17572 14:08:43.563119 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9936000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.573913 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.574159 clock_gettime(CLOCK_REALTIME, {1423721323, 574214000}) = 0
17572 14:08:43.574253 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9925000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.584885 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.585055 clock_gettime(CLOCK_REALTIME, {1423721323, 585081000}) = 0
17572 14:08:43.585147 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9936000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.595900 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.596170 clock_gettime(CLOCK_REALTIME, {1423721323, 596206000}) = 0
17572 14:08:43.596245 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9947000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.606960 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.607139 clock_gettime(CLOCK_REALTIME, {1423721323, 607167000}) = 0
17572 14:08:43.607232 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9935000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.617875 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.618119 clock_gettime(CLOCK_REALTIME, {1423721323, 618209000}) = 0
17572 14:08:43.618249 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9890000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.628960 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.629140 clock_gettime(CLOCK_REALTIME, {1423721323, 629168000}) = 0
17572 14:08:43.629231 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9935000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.639865 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.640134 clock_gettime(CLOCK_REALTIME, {1423721323, 640167000}) = 0
17572 14:08:43.640206 futex(0x580497a4, FUTEX_WAIT_PRIVATE, 1, {0, 9946000}) = -1 ETIMEDOUT (Connection timed out)
17572 14:08:43.650868 futex(0x58049028, FUTEX_WAKE_PRIVATE, 1) = 0
17572 14:08:43.651139 unlink("/tmp/hsperfdata_gamedata/17559") = 0
17572 14:08:43.651324 exit_group(0)     = ?

怎么那么多futex，google一查“futex connection time out”，嘿，还真有很多结果，最典型的就是leap second,中文翻译为“闰秒”，但仔细一看，上一次闰秒发生是2012年06月份，现在都2015年了，而且天天cpu都高，应该不是这个问题工具指望不上，只好看代码，代码看了后怀疑几个地方：

1）CountDownLatch：因为这个最有可能用到futex了，但实际想了想和验证了一下，这个东东不可能导致cpu这么高，真有这个问题，这东东完全就没法用了

2）多线程：看了代码，没有几个线程，而且业务就是一发一收，不可能多线程导致的

问题陷入僵局，怎么办呢？只好用终极大招了：分段注释！

1）注释响应处理的代码 —— 不行，cpu占用100%

2）注释发送请求的代码 —— 还是不行，，cpu占用100%

这不坑爹嘛，请求都不发，响应也没有了，你咋还这么慢？

3）干脆注释所有代码，只在main里面打印Hello world —— 还是不行，，cpu占用100%

这下就蛋疼了，没有任何业务，你cpu还高，这不坑我嘛

4）自己写个Hello world —— 咦，这次可以了，cpu占用1%左右

咋回事，同样都是打印Hello world，为啥cpu差别那么大？

左思右想，突然灵光一闪：

难道是和jvm加载类文件有关？

jvm在启动的时候会装载并连接所有除反射以外的类，而class文件是二进制的文件，需要从磁盘加载到内存然后解析，这种解析是很耗费cpu的，那么class文件越多，cpu耗费就越高，这正好解释了为什么同样输出Hello world，不同程序cpu占用率差别很大。

这个推论正好也解释了之前遇到的另外一个线上项目的现象：每次启动后有大约1分钟左右系统的cpu和负载很高，过了1分钟后就恢复正常了。

【建议】

需要重复运行的监控类程序，如果用java写，最好不要做成每次都要重新启动，而是在程序里面循环或者定时运行；

如果一定要每次都要重新启动，频率又很频繁的话，建议用shell、python之类的来写，否则一台机器运行太多java类的工具程序，会导致cpu和负载飙升

===============2015.02.13补充====================================

昨晚完成博客后，脑海中梳理整个流程发现还是有一点疑问：java虚拟机都是按需加载类的，那么我的main函数里面完全没有用到任何其它类，为何还是会加载呢？

今天针对这个问题继续查阅相关资料，发现原来所谓的“使用”，并不单单指我们通常编码所说看到的new、方法调用，而且还包括“依赖”。

举个简单例子：

package common;

import java.util.*;

public class CommonTester {

    public static void main(String[] args) {
        System.out.println("Hello, world......");
    }

    /**
     * 这个函数在main里面并没有调用，但jvm还是会加载ArrayList类，因为CommonTester内依赖了ArrayList类
     * @return
     */
    public List<String> createStringList(){
        return new ArrayList<String>(100);
    }
}

以上这个例子中，CommonTester类在main函数中并没有调用crateStringList方法，但因为CommonTester类依赖ArrayList类，那么在加载CommonTester的时候发现其依赖ArrayList类，就会先加载ArrayList类。所以，jvm最开始启动的时候肯定是先加载main函数所在的类，但是在加载这个类的时候发现依赖其它类，就会先加载其它类；加载其它类的时候也是这样处理，就像一个链式反应一样，所以基本上除了反射的类外，大部分类在jvm启动后，运行main函数前就已经加载完毕了。

为了验证这个推论，重新做了验证：

1）main函数所在的类注释所有其它代码，只保留main函数里面的打印语句

验证结果：cpu占用和自己写的简单的hello world程序一样，占用率大约1%左右

2）main函数所在的类注释所有其它代码，但保留import语句和main函数里面的打印语句

验证结果：和上面的一样，这个也很好理解，只保留import语句，因为这些语句并没有用，编译的时候这些语句都被优化掉了

==============2015.02.13第二次补充===========================

组内分享后，有同学又提出了一个疑问：jvm加载类的时候是多线程还是单线程？

为了回答这个问题，先后看了一些电子书和java官方的jvm规范，但都没有找到答案，于是决定自己来验证一下。

经过一番探索，终于找到1个很好的方法来判断类加载是单线程还是多线程。方法具体如下：

1）使用java -verbose启动程序，这样程序运行时就会打印加载的类

2）使用strace跟踪，就可以知道哪些线程加载了类

具体的命令为：strace -T -f -q -s 1024 -o strace.txt java -verbose ………….（省略号代表具体的程序运行相关参数）

通过查看strace输出的结果，发现如下现象：

1）多个线程都会去加载类

2）同一线程需要用到的类如果还没有加载，则自己会去加载，不会再委托给其它线程加载

注：验证环境的jvm信息如下，不同的虚拟机可能有不同的实现：

java version “1.6.0_31”
Java(TM) SE Runtime Environment (build 1.6.0_31-b04)
Java HotSpot(TM) 64-Bit Server VM (build 20.6-b01, mixed mode)

=============2015.07.13补充==================================

对于java6，有一个选项可以加快启动过程：-XX:CICompilerCount，对于线上业务，如果没有预热，启动后立刻有大量请求涌入，此时会出现cpu负载高，原因在于刚开始运行时Java都是解释执行，速度较慢，然后才逐渐用JIT将代码编译为本机二进制代码，JIT默认线程数只有2个，处理较慢。通过这个选项可以加快JIT的执行速度，降低启动后CPU负载高的时间。

但这个选项对于工具类java程序不能这样配置，同一台机器运行太多工具类，如果同时启动的话，因为线程数太多，负载会非常高

java7有一个自适应的选项：-XX:+TieredCompilation，能够根据CPU核数自动调整，有兴趣的同学可以研究一下

=======================================================

转载请注明出处：http://blog.csdn.net/yunhua_lee/article/details/43765371

转载请注明：SuperIT » java程序启动时cpu和负载高探索