JVM之CPU分析

一个load飙高的过程分析，非常有价值。
http://blog.csdn.net/axman/article/details/7104819

分类： 手记 故障分析 2011-12-27 11:50 2592人阅读 评论(3) 收藏 举报
ae的多语言应用中不断出现load飙高的情况 ，即使重启过10几个小时以后，cpu慢慢从1核到4核到被吃光。




而且集群中8台机器都是如此，所以应用方自己开始开分析原因。

前两天跟踪没结果，后来有一位同学根据tb达人的分析中得到启发：


关于us高和ys高的问题分析：

当us值过高时，表示运行的应用消耗大量的CPU。java应用造成us高的原因主要是线程一直处于可运行（Runnable）状态，通常这些线程在执行无阻塞、循环、正则或纯粹的计算等任务造成的；另外一个可能也会造成us高的原因是频繁GC。

当sy值高时，表示linux花费了更多的时间在进行java线程切换。java应用造成这种现象的主要原因是启动的线程比较多，且这些线程多数处于不断的阻塞（例如锁等待，IO等待状态）和执行状态的变化过程中，这就导致了操作系统要不断地切换执行的线程，产生大量的线程上下文切换。



以下代码用于验证上面的经验：

    public static void main(String[] args) {
        for (int i = 0; i < 500; i++) {
            new Thread().start();
        }
    }

    static class ComsumeCPURunnable implements Runnable {

        public void run() {
            long start = System.currentTimeMillis();
            long end = start;
            while (end - start < 10000) {
                end = System.currentTimeMillis();
            }
        }
    }

运行结果为：






模拟sy占用很高的代码：

    public static void main(String[] args) {
        for (int i = 0; i < 500; i++) {
            Object lock = new Object();
            new Thread(new RunnableA(lock)).start();
            new Thread(new RunnableB(lock)).start();
        }
    }

    static class RunnableA implements Runnable {

        private Object lock = null;

        public RunnableA(Object lock){
            this.lock = lock;
        }

        public void run() {

            while (true) {
                try {
                    synchronized (lock) {
                        lock.wait(50);
                    }
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
        }
    }

    static class RunnableB implements Runnable {

        private Object lock = null;

        public RunnableB(Object lock){
            this.lock = lock;
        }

        public void run() {
            while (true) {
                synchronized (lock) {
                    lock.notify();
                }
                try {
                    Thread.sleep(20);
                } catch (InterruptedException e) {                  
                    e.printStackTrace();
                }
            }
        }
    }


运行结果：






线上实际的情况是us很高；那原因就不在于线程等待或者阻塞导致的.


通过ps Lf [pid]命令可以看到所有java线程情况，cpu占用率、线程时间。可以看到占用cpu比较高的就几个线程：

UID        PID   PPID   LWP  C   NLWP STIME TTY      STAT   TIME

admin     10702 10692  11817 26  415    19:03 ?        Rl    65:19

admin     10702 10692  11807 16  415    19:03 ?        Rl    39:56

admin    10702 10692 11805 26  415 19:03 ?        Rl    65:32

admin    10702 10692 11801 26  415 19:03 ?        Rl    66:09

LWP(java线程id)，NLWP(java线程总数)

再通过jstack –l [pid]命令 dump java线程栈的情况，将以上线程id转换成16进制，后在dump出来的jstack文件中搜索，发现所有线程都属于xss过滤线程：

"TP-Processor59" daemon prio=10 tid=0x00002aab4b11b800 nid=0x450 runnable [0x0000000049fa7000]

   java.lang.Thread.State: RUNNABLE

  at xxxxxxxxxxxxxxxx....................
最后的问题定位于at xxxxxxxxxxxxxxxxx这里的二方库调用，问题被提交到我们这里时，我知道之前这个二方库存在一个死循环的bug并已经在新版本中解决，

直接通知应用方升级新版本的二方库测试一切正常，问题解决。




解决这样的问题，要求我们对　jps, jstack, jstat, top -p, jinfo, jmap等Java自身携带的工具，以及系统命(ps,pstree,pstack等)，Jvisualvm及所有的插件非常熟悉，

这些工具基本98%的以上问题能分析出来。

对于jstack做的ThreadDump的栈，可以反映如下信息。


如果某个相同的call stack经常出现， 我们有80%的以上的理由确定这个代码存在性能问题（读网络的部分除外）；

如果相同的call stack出现在同一个线程上（tid）上， 我们很很大理由相信， 这段代码可能存在较多的循环或者死循环；

如果某call stack经常出现， 并且里面带有lock，请检查一下这个lock的产生的原因， 可能是全局lock造成了性能问题；


在一个不大压力的群集里（w<2）， 我们是很少拿到带有业务代码的stack的， 并且一般在一个完整stack中， 最多只有1-2业务代码的stack，

如果经常出现， 一定要检查代码， 是否出现性能问题。


如果你怀疑有dead lock问题， 那么请把所有的lock id找出来，看看是不是出现重复的lock id。