java 问题定位

标签：

下面是我们遇到过的情况，如有错误或需要补充的内容，请直接修改。 
内存异常：
? java.lang.OutOfMemoryError: PermGen space
    》resin热部署，重新加载jar包，容易产生这种问题
    》持久代设置得太小也会导致这种问题，这时候需要修改jvm参数：-XX:PermSize=32m -XX:MaxPermSize=64m
    》这种情况测试环境常见，线上基本不会出现这种问题，我们的perm内存够用，而且会开启perm GC。
? java.lang.OutOfMemoryError: Java heap space
    》一般情况是从数据库或缓存加载了大量数据或者用户上传了大量文件，还有就是我们的代码问题，集合类使用不当，作用域的问题。
    》一般来说，由于会触发GC，只要代码不存在内存泄漏问题，线上很难出现这个异常。
    》解决办法：重启、修复代码隐患
? java.lang.OutOfMemoryError: GC overhead limit exceeded
    》这是因为使用并发收集算法进行GC，并且jvm启动参数中加了-XX:-UseGCOverheadLimit选项。
    》目前只在hive的应用中遇到此情况，线上应用一般是CMS算法，不会出现这种情况。
    》解决办法：增加heap size或者禁用上面那个选项。
? 很多时候内存异常并不会表现为异常，还没有达到这个临界点，你的系统就已经不可用了，这个时候需要主动去检查内存使用情况：
    》查询GC状态，看一下jvm是否在进行GC操作：
jstat -gcutil <pid> <time_span>[@tc-152-92 ~]$ jstat -gcutil 16590 3000  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT     0.00   0.00  85.96  90.60  54.20   3336    0.781 38188 13952.038 13952.819  0.00   0.00  91.42  90.60  54.20   3336    0.781 38189 13952.565 13953.346  0.00   0.00  97.43  90.60  54.20   3336    0.781 38190 13952.960 13953.741像上面这种情况就是有问题的：Full GC次数远大于Young GC次数，很不合理。Young GC一般都很快，而Full GC至少是100ms+(线上)，所以Full GC多的话我们就需要增大jvm的heap参数。    
    》查询java对象内存占用情况，看一下内存里的java对象是否合理。
[@zjm-110-88 ~]$ jmap -histo 2234 | head -10 num     #instances         #bytes  class name----------------------------------------------   1:       3373503     2209452824  [C   2:       3334031      133361240  java.lang.String   3:           260      101301344  [Lcom.caucho.util.LruCache$CacheItem;   4:        326846       63127704  [Ljava.lang.Object;   5:        151274       50828064  com.wap.sohu.mobilepaper.model.NewsContent   6:         19812       45474976  [I   7:        110209       40197776  [B   8:        145988       30902344  [Ljava.util.HashMap$Entry;   9:       1846859       29549744  java.lang.Object  10:        270121       19448712  com.wap.sohu.mobilepaper.model.xml.Image    

 ? 常用jvm参数：
        -XX:MaxPermSize=512m -XX:PermSize=512m -Xss128k
        -Xmx4096m -Xms4096m -Xmn1024m 
        -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=85 -XX:+PrintGCDetails 
        -XX:MaxTenuringThreshold=30
       
CPU异常：
? 运行的线程多了，我们的应用里有不少线程去异步地执行任务，可能某个时间点或事件触发了大量线程同时去执行操作，导致cpu资源紧张。
? 程序运行的慢了，比如大量的计算操作，频繁地进行循环遍历。
? io操作多，比如频繁地打印日志，频繁地进行网络访问（mysql,memcache)。
? 过多的同步操作。比如synchronize
? 一般情况下，我们都是通过观察jvm的栈信息来识别程序的异常，主要看java.lang.Thread.State这个值，一般BLOCKED和RUNNABLE都需要重点关注。BLOCKED状态肯定是有锁，比如频繁的IO操作会导致资源BLOCK或者我们代码里显式的加锁。RUNNABLE状态理论上是正常的，但是很有可能是逻辑处理太慢（比如网络io或计算）或调用频繁导致一段代码执行时间较长，这个也需要优化。
[@yd-80-133 ~]$ jstack 1344 2013-06-08 16:15:42Full thread dump Java HotSpot(TM) 64-Bit Server VM (20.8-b03 mixed mode): "pool-40-thread-5" prio=10 tid=0x000000005cea6800 nid=0x639c runnable [0x00000000493c5000]   java.lang.Thread.State: RUNNABLE        at java.net.SocketInputStream.socketRead0(Native Method)        at java.net.SocketInputStream.read(SocketInputStream.java:129)        at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)        at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)        at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)        - locked <0x000000074c115a08> (a com.mysql.jdbc.util.ReadAheadInputStream)        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3014)        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3467)        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3456)        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3997)        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2468)        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2629)        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2719)        - locked <0x0000000770fb3380> (a com.mysql.jdbc.JDBC4Connection)        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)        - locked <0x0000000770fb3380> (a com.mysql.jdbc.JDBC4Connection)        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2450)        - locked <0x0000000770fb3380> (a com.mysql.jdbc.JDBC4Connection)        at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2006)        - locked <0x0000000770fb3380> (a com.mysql.jdbc.JDBC4Connection)        at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1467)        - locked <0x0000000770fb3380> (a com.mysql.jdbc.JDBC4Connection)        at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeBatch(NewProxyPreparedStatement.java:1723)        at org.springframework.jdbc.core.JdbcTemplate$4.doInPreparedStatement(JdbcTemplate.java:873)        at org.springframework.jdbc.core.JdbcTemplate$4.doInPreparedStatement(JdbcTemplate.java:1)        at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:586)        at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:614)        at org.springframework.jdbc.core.JdbcTemplate.batchUpdate(JdbcTemplate.java:858)        at com.wap.sohu.mobilepaper.dao.statistic.StatisticDao$BatchUpdateTask2.run(StatisticDao.java:285)        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)        at java.lang.Thread.run(Thread.java:662)    
? 提供一种查看消耗cpu的线程的方式：
1. 找到java进程的id号，从top命令里可以看到消耗cpu最多的那个进程。下面是进程信息：[@tc-152-92 ~]$ ps -ef | grep 18950smc      18950     1 90 Dec19 ?        21:22:46 java -server -Xmx768m -Xms768m -Xss128k -Xmn300m -XX:MaxPermSize=128m -XX:PermSize=128m -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=85 -XX:+PrintGCDetails -XX:+UseMembar -Dhost_home=/opt/smc -Dserver_log_home=/opt/smc/log/server -Xloggc:/opt/smc/log/server/check_instance_gc.log -Dserver_ip=10.11.152.92 -Dserver_resources=/opt/smc/apps/server/server_apps/check_instance/resources/ -Dserver_name=check_instance com.wap.sohu.server.SmcApiServer 8010 2. 查看当时消耗cpu最多的线程：（-p 指定java进程号， -H 显示所有线程）[@tc-152-92 ~]$ top -p 18950 -H PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 18999 smc       16   0 1676m 1.0g  14m S 32.3  6.5 268:50.16 java                                                                                                           18997 smc       16   0 1676m 1.0g  14m S 30.4  6.5 267:47.97 java                                                                                                           18998 smc       17   0 1676m 1.0g  14m S 30.4  6.5 268:15.28 java                                                                                                           19000 smc       16   0 1676m 1.0g  14m S 30.4  6.5 268:06.23 java                                                                                                           19001 smc       15   0 1676m 1.0g  14m S  5.7  6.5  81:34.02 java  3. 保留当时的堆栈信息：[@tc-152-92 ~]$ jstack 18950 > 18950.txt 4. 把上面最消耗cpu的线程ID转成十六进制：[@tc-152-92 ~]$ pythonPython 2.4.3 (#1, Jun 11 2009, 14:09:37) [GCC 4.1.2 20080704 (Red Hat 4.1.2-44)] on linux2Type "help", "copyright", "credits" or "license" for more information.>>> hex(18999)‘0x4a37‘>>> 5. 在堆栈文件里查找这个十六进制的线程号：[@tc-152-92 ~]$ vim 18950.txt"Concurrent Mark-Sweep GC Thread" prio=10 tid=0x000000004183b800 nid=0x4a39 runnable"Gang worker#0 (Parallel CMS Threads)" prio=10 tid=0x0000000041834000 nid=0x4a35 runnable"Gang worker#1 (Parallel CMS Threads)" prio=10 tid=0x0000000041836000 nid=0x4a36 runnable"Gang worker#2 (Parallel CMS Threads)" prio=10 tid=0x0000000041837800 nid=0x4a37 runnable"Gang worker#3 (Parallel CMS Threads)" prio=10 tid=0x0000000041839800 nid=0x4a38 runnable 这里发现都是gc线程在消耗cpu，从最上面的进程信息可以看到这个java进程只开了1G的堆，top信息里显示的内存占用已经到1G了，正好能对上。    


代码里的常见异常：
? java.lang.OutOfMemoryError: unable to create new native thread
程序里起的线程太多了。一种情况是启动程序的用户（smc）最大可运行线程有限制(ulimit -a查看)，另一种情况就是代码里起了很多线程。
当这种异常出现时，我们登录到服务器上当前用户下会出现Resource temporarily unavailable的错误。（如果是root用户启动的进程，就只能重启机器了）
? Broken Pipe  // TODO...
? Too many open files   // TODO...
? c3p0连接池异常:Attempted to use a closed or broken resource pool
<property name="breakAfterAcquireFailure" value="true"></property>
改成:
<property name="breakAfterAcquireFailure" value="false"></property>
如果参数为true,只要有一次获取数据库连接失败后,整个数据源就会声明为断开并永久关闭,服务就不可用了.
如果参数为false,获取数据库连接失败后程序会抛出异常,但是数据源仍然有效,等下次尝试获取连接成功后就可以正常使用了. 
? 类初始化异常
java.lang.NoClassDefFoundError: Could not initialize class com.wap.sohu.mobilepaper.util.ClientUserCenterHttpUtils
    > 可能是你的classpath路径不对，或类加载顺序的问题(jar冲突)，jinfo <pid>  查看java.class.path属性
    > 类文件不存在
    > 类初始化时抛出未捕获的异常，比如static块或static变量初始化有问题。
   
在线Debug方式
安装：10.10.76.79:/root/btrace-bin.tar.gz 把这个文件拷到目标机器上，新建一个btrace的目录，解压即可用：tar -zxvf btrace-bin.tar.gz -C btrace/
修改权限：cd bin/;    chmod 744 *
编写Btrace脚本，比如我们要监控一个方法的输入参数和输出内容：
import com.sun.btrace.annotations.*;import static com.sun.btrace.BTraceUtils.*;import java.util.*;@BTracepublic class Response {  @OnMethod(clazz="com.sohu.smc.reply.core.LocalCache", method="getBulk", location=@Location(Kind.RETURN))  public static void onGetBulk(String[] keys, @Return Map<String, Object> result) {    println("=======================================");    printArray(keys);    println(strcat("Params keys length:", str(keys.length)));    println(strcat("Result length:", str(size(result))));  }//    @OnMethod(clazz="com.sohu.smc.reply.core.CommentCursorList", method="getIdList", location=@Location(Kind.RETURN))//    public static void onGetIdList(@Return List<Long> result) {//      println(strcat("ID LIST:", str(size(result))));//    }}    
运行这个脚本（samples目录下提供了很多例子，基本都可以直接拿来用）：
[smc@bx-0-157 bin]$ ./bin/btrace -cp build/ 15631 Response.java     =======================================[]Params keys length:0Result length:0=======================================[rp_482712136, rp_482665158, rp_482662804, ]Params keys length:3Result length:3    
btrace运行后会对线上jvm造成一定的影响，我们最好是重启一下jvm实例，恢复正常状态。
          btrace常用的场景有：监控方法响应时间，监控线程启动，类加载，异常信息（有时候我们的代码会吃掉异常，看不到具体哪行代码产生的）。

java 问题定位

标签：

原文地址：http://my.oschina.net/u/1388024/blog/418599