Java线上应用故障排查之一：高CPU占用

转http://blog.csdn.net/blade2001/article/details/9065985

 

先确定pid：

top

找到最消耗cpu的进程15495

 

再确定tid：

ps -mp 15495 -o THREAD,tid,time

找到最占用cpu的进程18448

 

printf "%x\n" 18448

4810

 

打印堆栈

jstack 15495 | grep 4810 -A 30

 

例如发现栈如下：

"regionserver60020-smallCompactions-1438827962552" daemon prio=10 tid=0x00007f4ce1903800 nid=0xe2a72 runnable [0x00007f443b8f6000]
   java.lang.Thread.State: RUNNABLE
        at com.hadoop.compression.lzo.LzoDecompressor.decompressBytesDirect(Native Method)
        at com.hadoop.compression.lzo.LzoDecompressor.decompress(LzoDecompressor.java:315)
        - locked <0x00007f450c42d820> (a com.hadoop.compression.lzo.LzoDecompressor)
        at org.apache.hadoop.io.compress.BlockDecompressorStream.decompress(BlockDecompressorStream.java:88)
        at org.apache.hadoop.io.compress.DecompressorStream.read(DecompressorStream.java:85)
        at java.io.BufferedInputStream.read1(BufferedInputStream.java:273)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:334)
        - locked <0x00007f4494423b70> (a java.io.BufferedInputStream)
        at org.apache.hadoop.io.IOUtils.readFully(IOUtils.java:192)
        at org.apache.hadoop.hbase.io.compress.Compression.decompress(Compression.java:439)
        at org.apache.hadoop.hbase.io.encoding.HFileBlockDefaultDecodingContext.prepareDecoding(HFileBlockDefaultDecodingContext.java:91)
        at org.apache.hadoop.hbase.io.hfile.HFileBlock$FSReaderV2.readBlockDataInternal(HFileBlock.java:1522)
        at org.apache.hadoop.hbase.io.hfile.HFileBlock$FSReaderV2.readBlockData(HFileBlock.java:1314)
        at org.apache.hadoop.hbase.io.hfile.HFileReaderV2.readBlock(HFileReaderV2.java:358)
        at org.apache.hadoop.hbase.io.hfile.HFileReaderV2$AbstractScannerV2.readNextDataBlock(HFileReaderV2.java:610)
        at org.apache.hadoop.hbase.io.hfile.HFileReaderV2$ScannerV2.next(HFileReaderV2.java:724)
        at org.apache.hadoop.hbase.regionserver.StoreFileScanner.next(StoreFileScanner.java:136)
        at org.apache.hadoop.hbase.regionserver.KeyValueHeap.next(KeyValueHeap.java:108)
        at org.apache.hadoop.hbase.regionserver.StoreScanner.next(StoreScanner.java:507)
        at org.apache.hadoop.hbase.regionserver.compactions.Compactor.performCompaction(Compactor.java:217)
        at org.apache.hadoop.hbase.regionserver.compactions.DefaultCompactor.compact(DefaultCompactor.java:76)
        at org.apache.hadoop.hbase.regionserver.DefaultStoreEngine$DefaultCompactionContext.compact(DefaultStoreEngine.java:109)
        at org.apache.hadoop.hbase.regionserver.HStore.compact(HStore.java:1106)
        at org.apache.hadoop.hbase.regionserver.HRegion.compact(HRegion.java:1482)
        at org.apache.hadoop.hbase.regionserver.CompactSplitThread$CompactionRunner.run(CompactSplitThread.java:475)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)

 是读写hfile发生的错误，导致启动多个runnable

 

 

 

 

 

一个应用占用CPU很高，除了确实是计算密集型应用之外，通常原因都是出现了死循环。

（友情提示：本博文章欢迎转载，但请注明出处：hankchen，http://www.blogjava.net/hankchen）

以我们最近出现的一个实际故障为例，介绍怎么定位和解决这类问题。

根据top命令，发现PID为28555的Java进程占用CPU高达200%，出现故障。

通过ps aux | grep PID命令，可以进一步确定是tomcat进程出现了问题。但是，怎么定位到具体线程或者代码呢？

首先显示线程列表:

ps -mp pid -o THREAD,tid,time

找到了耗时最高的线程28802，占用CPU时间快两个小时了！

其次将需要的线程ID转换为16进制格式：

printf "%x\n" tid

最后打印线程的堆栈信息：

jstack pid |grep tid -A 30

找到出现问题的代码了！

现在来分析下具体的代码：ShortSocketIO.readBytes(ShortSocketIO.java:106)

ShortSocketIO是应用封装的一个用短连接Socket通信的工具类。readBytes函数的代码如下：

public byte[] readBytes(int length) throws IOException {

    if ((this.socket == null) || (!this.socket.isConnected())) {

        throw new IOException("++++ attempting to read from closed socket");

    }

    byte[] result = null;

    ByteArrayOutputStream bos = new ByteArrayOutputStream();

    if (this.recIndex >= length) {

           bos.write(this.recBuf, 0, length);

           byte[] newBuf = new byte[this.recBufSize];

           if (this.recIndex > length) {

               System.arraycopy(this.recBuf, length, newBuf, 0, this.recIndex - length);

           }

           this.recBuf = newBuf;

           this.recIndex -= length;

    } else {

           int totalread = length;

           if (this.recIndex > 0) {

                totalread -= this.recIndex;

                bos.write(this.recBuf, 0, this.recIndex);

                this.recBuf = new byte[this.recBufSize];

                this.recIndex = 0;

    }

    int readCount = 0;

    while (totalread > 0) {

         if ((readCount = this.in.read(this.recBuf)) > 0) {

                if (totalread > readCount) {

                      bos.write(this.recBuf, 0, readCount);

                      this.recBuf = new byte[this.recBufSize];

                      this.recIndex = 0;

               } else {

                     bos.write(this.recBuf, 0, totalread);

                     byte[] newBuf = new byte[this.recBufSize];

                     System.arraycopy(this.recBuf, totalread, newBuf, 0, readCount - totalread);

                     this.recBuf = newBuf;

                     this.recIndex = (readCount - totalread);

             }

             totalread -= readCount;

        }

   }

}

问题就出在标红的代码部分。如果this.in.read()返回的数据小于等于0时，循环就一直进行下去了。而这种情况在网络拥塞的时候是可能发生的。

至于具体怎么修改就看业务逻辑应该怎么对待这种特殊情况了。

 

最后，总结下排查CPU故障的方法和技巧有哪些：

1、top命令：Linux命令。可以查看实时的CPU使用情况。也可以查看最近一段时间的CPU使用情况。

2、PS命令：Linux命令。强大的进程状态监控命令。可以查看进程以及进程中线程的当前CPU使用情况。属于当前状态的采样数据。

3、jstack：Java提供的命令。可以查看某个进程的当前线程栈运行情况。根据这个命令的输出可以定位某个进程的所有线程的当前运行状态、运行代码，以及是否死锁等等。

4、pstack：Linux命令。可以查看某个进程的当前线程栈运行情况。

 

（友情提示：本博文章欢迎转载，但请注明出处：hankchen，http://www.blogjava.net/hankchen）