一次服务大量超时的java排查过程经验
2013-10-09 00:08
836 查看
一次应用提供的服务化接口收到报警大量超时,报404.赶忙着手处理:
1)查看监控报表的cpu load ,jvm gc情况,jvm内存,io都正常,如果没有做监控可以手工到服务器上命令查看
2)检查网络包括http响应及tcp网络响应请求情况均正常
3)登陆服务器,jps -v把java进程打出来,或者top发现j该java进程的cpu使用率及内存占用率均正常
4)top -H -p PID 命令查看该进程里对应的当前线程数量正常,各线程占用的cpu和内存正常.和上次cpu load过高时不一样,当时的线程是有几个占用了较高的cpu.
5)jstack pid 打出来一台服务超时和一台重启后正常提供服务的stack信息,发现差不多,都有类似信息:
发现有问题的这台机器单个线程出现上面的信息较多,正常服务的服务器打出来的线程上面的并发销等待信息较少
对上面信息分析后,结合自己的应用情况得到下面的信息:
应用报404是做了超时控制,请求大于500ms就报404请求,监控到后台服务平均响应基本是1000ms左右.从日志报错情况来看,有一个搜索的接口不停打超时日志,但咨询接口方说该接口正常.这个接口是http请求,curl这个请求返回正常.
但异步加载框架设置的超时刚好1秒钟.所以基本断定这个接口不可用,直接给异步框架做超时控制1秒钟返回,因为大于500ms直接报404.
重启后的机器这个接口没有报错,说明connection出现了问题.
至于为什么突然出现这个问题,这个错误的信息很重要,初步看是nio报的,问题远没想象的简单.后继再找接口方排查
最后确认是dubbo的一个bug,导致配置的业务线程池无效,线程会无限增长,所以会导致线程无限堆积和大量空等待线程,导致内存,gc的cpu开销过大,间而导至load过高。后面升级dubbo版本修复。
1)查看监控报表的cpu load ,jvm gc情况,jvm内存,io都正常,如果没有做监控可以手工到服务器上命令查看
2)检查网络包括http响应及tcp网络响应请求情况均正常
3)登陆服务器,jps -v把java进程打出来,或者top发现j该java进程的cpu使用率及内存占用率均正常
4)top -H -p PID 命令查看该进程里对应的当前线程数量正常,各线程占用的cpu和内存正常.和上次cpu load过高时不一样,当时的线程是有几个占用了较高的cpu.
5)jstack pid 打出来一台服务超时和一台重启后正常提供服务的stack信息,发现差不多,都有类似信息:
"DubboClientHandler-172.22.35.17:9090-thread-5" daemon prio=10 tid=0x00002aaab85fa800 nid=0x50d9 waiting on condition [0x0000000041c6a000] java.lang.Thread.State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x0000000793f97040> (a java.util.concurrent.SynchronousQueue$TransferStack) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198) at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424) at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323) at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907) at java.lang.Thread.run(Thread.java:662) "DubboClientHandler-172.22.11.33:9090-thread-5" daemon prio=10 tid=0x00002aaab9e2f800 nid=0x50d3 waiting on condition [0x00000000492bc000] java.lang.Thread.State: TIMED_WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x0000000793c2b708> (a java.util.concurrent.SynchronousQueue$TransferStack) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198) at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424) at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323) at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907) at java.lang.Thread.run(Thread.java:662)6)执行 jstack [进程pid]|grep -A 100 [线程pid]
发现有问题的这台机器单个线程出现上面的信息较多,正常服务的服务器打出来的线程上面的并发销等待信息较少
对上面信息分析后,结合自己的应用情况得到下面的信息:
应用报404是做了超时控制,请求大于500ms就报404请求,监控到后台服务平均响应基本是1000ms左右.从日志报错情况来看,有一个搜索的接口不停打超时日志,但咨询接口方说该接口正常.这个接口是http请求,curl这个请求返回正常.
但异步加载框架设置的超时刚好1秒钟.所以基本断定这个接口不可用,直接给异步框架做超时控制1秒钟返回,因为大于500ms直接报404.
重启后的机器这个接口没有报错,说明connection出现了问题.
至于为什么突然出现这个问题,这个错误的信息很重要,初步看是nio报的,问题远没想象的简单.后继再找接口方排查
最后确认是dubbo的一个bug,导致配置的业务线程池无效,线程会无限增长,所以会导致线程无限堆积和大量空等待线程,导致内存,gc的cpu开销过大,间而导至load过高。后面升级dubbo版本修复。
相关文章推荐
- 记一次java进程被linux杀掉的排查过程
- hadoop中的一次集群任务执行超时问题查找过程
- 记一次磁盘IO高问题排查过程
- 记一次Linux系统被入侵的排查过程(一)
- 记一次神奇的优化过程:Java反射 VS Apache BeanUtils VS Spring BeanUtils
- 记录一次java优化过程
- java 一次CPU占用过高问题的排查及解决
- [java]微服务架构连载No4 Hystrix+Dashboard+Turbine实现断路器(限流,超时,异常...)和服务监控
- 一次php进程诡异退出的排查过程
- 一次批量修改博客文章的经验(下):操作过程
- 记一次Oracle数据库连接不释放问题排查过程
- 运维经验分享(四)--关于 java进程管理的服务控制脚本编程思路分析
- 记一次调bug的过程:windows下查找java应用程序CPU与内存过高
- 10.zabbix学习笔记:记一次zabbix故障引发的排查过程
- Cordys 排查过程 【Cordys服务启动错误】
- android4.0网络服务状态或者信号量强度上报过程(RIL Framework Java 部分)
- http服务详解(1)——一次完整的http服务请求处理过程
- 一次应用服务拆分架构改造过程
- 记一次集群内无可用http服务问题排查
- 编译工程时报java:[1,0] illegal character: \65279问题排查与解决过程