您好,欢迎访问一九零五行业门户网

Java问题定位解决方法总结

背景
   “线下没问题的”、 “代码不可能有问题 是系统原因”、“能在线上远程debug么”
    线上问题不同于开发期间的bug,与运行时环境、压力、并发情况、具体的业务相关。对于线上的问题利用线上环境可用的工具,收集必要信息 对定位问题十分重要。
    对于导致问题的bug、资源瓶颈很难直观取得数据,需要根据资源使用数据、日志等信息推测问题根源。并且疑难问题的定位通常需要使用不同的方法追根溯源。
    这篇wiki我对自己使用过的工具做了整理,并分享一些案例。
1.  常见问题
1.1 可用性
    这里举几种常见导致服务可用性的情况:
a) 502 bad gateway
对应用系统特别是基于http的应用最严重的莫过于502 bad gateway,这表示后端服务已经完全不可用,可能原因
    资源不足1:垃圾回收导致,在cms在应用内存泄漏或内存不足情况下会导致严重的应用暂停。
    资源不足2:服务器线程数不足,常见web server如tomcat  jetty都是有最大工作线程配置的
    资源不足3:数据库资源不足,数据库通常使用连接池配置,maxconnection配置低加上过多慢查询会block住web server的工作线程
    资源不足4:io资源瓶颈,线上环境io是共享的,尤其对于混布环境(crm还好 没有这种情况,但是有很多agent),我们常用的log4j日志工具对于每个记录的日志文件也是一种独占资源,线程先要获得锁才能向日志记录数据。
    ... ...
    各种oom
b) socket异常
常见connection reset by peer,broken pipe,eofexception
    网络问题:在跨运营商、机房访问情况下可能遇到
    程序bug:socket异常关闭
1.2 平均响应时间
系统发生问题时最直观的表象,这个参数在情况恶化传染其他服务 导致整个系统不可用前,可以提前预警,可能原因:
    资源竞争1:cpu
    资源竞争2:io
    资源竞争3:network io
    资源竞争4:数据库
    资源竞争5:solr、medis
    下游接口:异常导致响应延时
1.3 机器报警
与应用服务不可用相比,这类错误不会直接导致服务不可用,而且如果存在混不,机器部署多个服务可能相互干扰:
    cpu
    磁盘
    fd
    io(网络 磁盘)
1.4 小结
写了半天,很多情况是重复提到,通常线上问题的原因不外乎系统资源、应用程序,掌握监控查看这些资源、数据的工具就更容易定位线上的问题。
2常用工具
2.1 linux工具
a) sysstat:
    iostat:查看读写压力
    [sankuai@cos-mop01 logs]$ iostat     linux 2.6.32-20131120.mt (cos-mop01.lf.sankuai.com)     2015年10月21日     _x86_64_    (4 cpu)     avg-cpu:  %user   %nice %system %iowait  %steal   %idle                1.88    0.00    0.87    0.12    0.05   97.07     device:            tps   blk_read/s   blk_wrtn/s   blk_read   blk_wrtn     vda               1.88        57.90        12.11 2451731906  512911328     vdb               0.01         0.40         1.41   17023940   59522616     vdc               1.14        28.88        36.63 1223046988 1551394969
sar:查看cpu 网络io io,开启参数可以查看历史数据
    /etc/sysconfig/sysstat     history=7     /etc/cron.d/sysstat     */10 * * * * root /usr/lib/sa/sa1 1 1             sar -u/-r/-b/-b/-q/-p/-n -f /var/log/sa/sa09
b) top
关注load、cpu、mem、swap
可按照线程查看资源信息(版本大于3.2.7)
top - 19:33:00 up 490 days,  4:33,  2 users,  load average: 0.13, 0.39, 0.42 tasks: 157 total,   1 running, 156 sleeping,   0 stopped,   0 zombie cpu(s):  4.9%us,  2.7%sy,  0.0%ni, 92.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.3%st mem:   5991140k total,  5788884k used,   202256k free,     4040k buffers swap:  2096440k total,   447332k used,  1649108k free,   232884k cached   pid user      pr  ni  virt  res  shr s %cpu %mem    time+  swap code data command 18720 sankuai   20   0 8955m 4.3g 6744 s 22.6 74.5 174:30.73    0    4 8.6g java 27794 sankuai   20   0 5715m 489m 2116 s 11.6  8.4   3922:43 121m    4 3.9g java 13233 root      20   0  420m 205m 2528 s  0.0  3.5   1885:15  91m    4 304m puppetd 21526 sankuai   20   0 2513m  69m 4484 s  0.0  1.2  45:56.28  37m    4 2.4g java
c) vmstat
[sankuai@cos-mop01 logs]$ vmstat procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----  r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st  0  0 447332 200456   4160 234512    0    0    11     6    0    0  2  1 97  0  0
d) tcpdump
定位网络问题神器,可以看到tcpip报文的细节,需要同时熟悉tcpip协议,可以和wireshark结合使用。
常见场景分析网络延迟、网络丢包,复杂环境的网络问题分析。
#!/bin/bash tcpdump -i eth0 -s 0 -l -w - dst port 3306 | strings | perl -e ' while(a8093152e673feb7aba1828c43532094) { chomp; next if /^[^ ]+[ ]*$/;     if(/^(select|update|delete|insert|set|commit|rollback|create|drop|alter|call)/i)     {         if (defined $q) { print $q\n; }         $q=$_;     } else {         $_ =~ s/^[ \t]+//; $q.= $_;     } }'
3.2 java工具
a) jstat
[sankuai@cos-mop01 logs]$ jstat -gc 18704  s0c    s1c    s0u    s1u      ec       eu        oc         ou       mc     mu    ccsc   ccsu   ygc     ygct    fgc    fgct     gct 3584.0 3584.0  0.0    0.0   24064.0  13779.7   62976.0      0.0     4480.0 677.9  384.0   66.6       0    0.000   0      0.000    0.000
b) jmap
jmap -dump:format=b,file=heap.bin $pid
c) jstack or kill -3
查看死锁、线程等待。
线程状态:
    running
    timed_waiting(on object monitor) 
    timed_waiting(sleeping) 
    timed_waiting(parking) 
    wainting(on object monitor) 
d) jhat jconsole
jhat很难用 jconsole通过jmx取信息对性能有影响
e) gc日志
-xx:+useparallelold
-xx:+concurrentmultisweep
3.3 第三方工具
a) mat
对象详细
inboud/outbound
thread overview
配置项
./memoryanalyzer -keep_unreachable_objects  heap_file
4. 案例分析
4.1 cpu高
现象:cpu报警
定位问题:
    查看cpu占用高的线程
sankuai@sin2:~$ ps h -eo user,pid,ppid,tid,time,%cpu|sort -rnk6 |head -10 sankuai 13808 13807 13808 00:00:00 8.4 sankuai 29153 1 29211 00:21:13 0.9 sankuai 29153 1 29213 00:20:01 0.8 sankuai 29153 1 29205 00:17:35 0.7 sankuai 29153 1 29210 00:11:50 0.5 sankuai 29153 1 1323 00:08:37 0.5 sankuai 29153 1 29207 00:10:02 0.4 sankuai 29153 1 29206 00:07:10 0.3 sankuai 29153 1 29208 00:06:44 0.2
thread dump
jstack $pid > a.txt printf %x $tid $xtid
查找线程执行的代码
"main-sendthread(cos-zk13.lf.sankuai.com:9331)" #25 daemon prio=5 os_prio=0 tid=0x00007f78fc350000 nid=$tidx runnable [0x00007f79c4d09000] java.lang.thread.state: runnable at org.apache.zookeeper.clientcnxn$sendthread.run(clientcnxn.java:1035) at java.util.concurrent.futuretask.run(futuretask.java:266) at java.util.concurrent.threadpoolexecutor.runworker(threadpoolexecutor.java:1142) at java.util.concurrent.threadpoolexecutor$worker.run(threadpoolexecutor.java:617) at java.lang.thread.run(thread.java:745)
4.2 io高
现象:磁盘io报警
环境:需要安装sysstat工具
定位问题:
a) 查看cpu占用高的线程
1
pidstat -d -t -p $pid
b) 其他同4.1
4.3 资源
a) 数据库
"db-processor-13" daemon prio=5 tid=0x003edf98 nid=0xca waiting for monitor entry [0x000000000825f000] java.lang.thread.state: blocked (on object monitor) at connectionpool.getconnection(connectionpool.java:102) - waiting to lock <0xe0375410> (a beans.connectionpool) at service.getcount(servicecnt.java:111) at service.insert(servicecnt.java:43) "db-processor-14" daemon prio=5 tid=0x003edf98 nid=0xca waiting for monitor entry [0x000000000825f020] java.lang.thread.state: blocked (on object monitor) at connectionpool.getconnection(connectionpool.java:102) - waiting to lock <0xe0375410> (a beans.connectionpool) at service.getcount(servicecnt.java:111) at service.insertcount(servicecnt.java:43)
b) log
"rmi tcp connection(267865)-172.16.5.25" daemon prio=10 tid=0x00007fd508371000 nid=0x55ae waiting for monitor entry [0x00007fd4f8684000] java.lang.thread.state: blocked (on object monitor) at org.apache.log4j.category.callappenders(category.java:201) - waiting to lock <0x00000000acf4d0c0> (a org.apache.log4j.logger) at org.apache.log4j.category.forcedlog(category.java:388) at org.apache.log4j.category.log(category.java:853) at org.apache.commons.logging.impl.log4jlogger.warn(log4jlogger.java:234) at com.xxx.core.common.lang.cache.remote.memcachedclient.get(memcachedclient.java:110)
c) web server
有两个非常重要的系统参数:
maxthread: 工作线程数
backlog:tcp连接缓存数,jetty(serverconnector.acceptqueuesize) tomcat(connector.acceptcount),高并发下设置过小会有502
4.4 gc
a) cms fail
promotion failed
172966 2015-09-18t03:47:33.108+0800: 627188.183: [gc 627188.183: [parnew (promotion failed) 172967 desired survivor size 17432576 bytes, new threshold 1 (max 6) 172968 - age 1: 34865032 bytes, 34865032 total 172969 : 306688k->306688k(306688k), 161.1284530 secs]627349.311: [cms cms: abort preclean due to time 2015-09-18t03:50:14.743+0800: 627349.818: [cms-concurrent-abortable-preclean: 1.597/162.729 secs] [times: user=174.58 sys=84.57, real=162.71 secs] 172970 (concurrent mode failure): 1550703k->592286k(1756416k), 2.9879760 secs] 1755158k->592286k(2063104k), [cms perm : 67701k->67695k(112900k)], 164.1167250 secs] [times: user=175.61 sys=84.57, real=164.09 secs]
concurrent fail
[cms2015-09-18t07:07:27.132+0800: 639182.207: [cms-concurrent-sweep: 1.704/13.116 secs] [times: user=17.16 sys=5.20,real=13.12 secs] 443222 (concurrent mode failure): 1546078k->682301k(1756416k), 4.0745320 secs] 1630977k->682301k(2063104k), [cms perm :67700k->67693k(112900k)], 15.4860730 secs] [times: user=19.40 sys=5.20, real=15.48 secs]
b) 连续full gc
应用存在内存泄漏,垃圾收集会占用系统大量cpu时间,极端情况下可能发生90%以上时间在做gc的情况。
在系统使用http访问check alive或者使用了zookeeper这种通过心跳保证存活性的应用中,会可用性异常或者被zk的master剔除。
5. 注意
    保留现场:threaddump top heapdump
    注意日志记录:文件 数据库
以上就是java问题定位解决方法总结的详细内容。
其它类似信息

推荐信息