转载

运维问题分析02(12.20)

在整个平台的运维过程中，我们始终要意识到一点，就是对于任何运维类故障或问题，如果没有真正找到问题的根源，各种临时处理措施类似重启等都不算真正的解决问题。因为根源没有最终解决，始终就是平台运行稳定性的一个定时炸弹，随时都可能会爆发出来造成更大的系统运行故障。

问题一定要分析到根源，并针对根源制定解决方案和措施，这是问题分析和管理的最基本逻辑。

还是回到最近的OSB集群出现的一次连接超时，JVM内存溢出的问题分析来说。

首先还是说下问题的表现形式，最大的表现是服务消费出现长耗时或等待超时，而在OSB Admin集群节点能够观察到的就是Admin Server管理台打开很慢，打开后可以看到不少的集群节点处于黄色告警状态，可能部分节点已经自动触发重启。

而在管控平台我们可以检测到的情况是

1. 在异常日志监控中，会监控到系统异常，提升信息为JVM堆内存溢出或管道破裂

2. 在服务日志监控中可以发现大量服务消费时长超过100s，或者服务调用总时长是源时长的数倍

从后续运维监控角度来看，我们也需要增加第1点和第2点的实时监控和预警功能，对当前的服务心跳检查功能进行改进，能够做到分钟级的实时监测和预警。而这实时监测后续还可以放到大屏看板上面。

对于问题分析，我们再来看下前面的一些分析思路

首先对于内存溢出情况，我们最常见的就是要分析是否存在大数据量大并发调用，因此我们是先对服务消费日志数据进行导出分析，发现在这个时间区间并没有出现特别的大数据量服务调用和消费。同时对于服务调用并发量也很往日持平。

其次分析有无长耗时的服务消费，经过服务日志实例数据分析，发现有两个服务存在服务消费时长较长的情况，一个是在10s左右，一个服务是个别出现20S到40S的源服务耗时，但是根据报文来看这些服务本身的输入和输出数据量并不大，不确定是和该因素有关系。

由于对于并发量大的查询服务消费，我们当前关闭了详细服务日志Log的功能，导致我们很难在问题排查的时候进行详细的输入和输出报文分析，这也给问题诊断和最终定位造成了困难。因此，这也需要后续对所有服务打开服务日志记录功能，同时对并发量大的服务调用采用单表进行服务日志记录，并定期清除。这块需要做到灵活的可配置能力，动态配置服务和目标数据表之间的映射关系。

今天又进一步对OSB Server的Log日志进行了分析，只选择了集群中的一个节点进行分析，具体分析如下：

在3:14分有JVM内存检测日志，当时内存还剩余60%

到3:24分检测的时候，内存剩余20%

到3:25分检测的时候，内存只剩余2%

提取这11分钟的日志进行分析，发现整体服务消费实例日志中，出现超过1M的报文量并不到，只有1.6m，而且这10分钟出现的次数只有30多次，总时长也不长，都在1S内就正常返回。那么为何会出现内存持续增长而没有释放的问题？这个是找到问题的一个关键点。

在Log到内存只剩余20%的后，开始出现如下Log警告信息

BEA-002936 maximum thread constraint weblogic.unicast.DispatchWorkManager is reached

BEA-002936 maximum thread constraint ClusterMessaging is reached

根据提示应该是达到了最大线程约束，也就是说连接没有被释放掉，是什么导致连接不能快速是否，从服务调用耗时来看无法找到原因，这段时间的服务调用时长基本都在1S之内，为何连接没有快速释放掉？这也是没有找到具体的原因点在哪里？

在报出最大线程约束警告后，接着Log里面监控到如下警告信息：

Service guardian is 10127ms late

indicating that this JVM may be running slowly or experienced a long GC

即集群管理器监控到集群节点的JVM在进行GC垃圾回收的时候响应缓慢，那么这个响应缓慢究竟是什么原因导致无法进行GC操作，暂时没有找到原因。

在出现该日志提示后，我们在节点服务器发现，Admin节点在将慢的集群节点从整个Cluster集群中移除，这个有具体的日志记录，类似如下：

BEA-000112 Removing osb_server24_1 with ID from Cluster due to timeout

即由于集群节点检测超时，而将集群节点移除，在移除后后面也看到有重新挂接的Log日志。

BEA-000111 Adding osb_server24_1 with ID to Cluster

大约在3点40分左右，在日志里面才记录到有内存溢出和管道破裂的错误。

java.net.SocketException: Broken pipe (Write failed)

at java.net.SocketOutputStream.socketWrite0(Native Method)

at weblogic.socket.SocketMuxer.internalWrite(SocketMuxer.

at weblogic.socket.SocketMuxer.write(SocketMuxer.

所以通过当前的OSB日志记录，需要进一步明确的就是是什么导致在10分钟时间里面内存使用率快速增长，同时又服务进行快速的GC垃圾回收。是由于服务并发量大引起，还是由于大数据量报文引起，究竟是哪个具体的服务引起了该问题。而这些暂时无法从日志里面得到更加详细的信息，同时前面也说了由于当前一些服务调用详细报文日志处于关闭状态，也增加了我们解决该问题的难度。

最后在总结下从日志能够发现的问题出现过程如下：

1. 首先是OSB集群节点监控内存使用，发现内存使用率不断提高并有耗尽趋势

2. 监控发现已经达到最大线程数限制，无可用连接可使用

3. 监控到部门OSB集群节点响应缓慢或超时，因此对这些集群节点从集群中摘除并重新挂接

4. 提升集群进行在进行GC垃圾回收操作的时候相对缓慢，同时监控到内存耗尽

5. 出现内存溢出和管控破裂的异常错误

这个问题出现过程还是很清晰，但是关键问题还是究竟是哪个服务导致的问题，或者说确实是服务并发量巨大导致的连接不够用问题，这个需要最终确认。

原文 http://blog.sina.com.cn/s/blog_493a84550102yld7.html

正文到此结束