2014-7-22 2个故障分析处理

1.现象

主要现象：2个服务器都出现了tb_0031的发送状态长时间为0或4的状态.重起服务后才正常发送完的情况。

2.日志分析

2.1sui_b日志分析

日志中出现大量的以下错误.

[2014-07-21 00:01:01:048][线程2588932][2][20][0][]default CSEMQ::Inquiry...
[2014-07-21 00:01:01:298][线程2588932][4][20][0][]CAPBase::GetOrg orgid=0,ret=-30974,错误:DB_RUNRECOVERY: Fatal error, run database recovery.
[2014-07-21 00:01:01:298][线程2588932][4][20][0][]CAPBase::GetOrg orgid=0,ret=-30974,错误:DB_RUNRECOVERY: Fatal error, run database recovery.
[2014-07-21 00:01:01:298][线程2588932][4][20][0][]CAPBase::GetOrg orgid=20332,ret=-30974,错误:DB_RUNRECOVERY: Fatal error, run database recovery.

直到9:00多重起前，期间几乎全部是上面的错误内容。

由于Berkeley DB的DB_RUNRECOVERY问题，也导致下面的错误：

[2014-07-21 00:47:20:314][线程2589176][4][20][0][]CAPBase::GetOrg orgid=10007,ret=-30974,错误:DB_RUNRECOVERY: Fatal error, run database recovery.
[2014-07-21 00:47:20:314][线程2589176][4][20][0][]CAPBase::GetOrg orgid=10007,ret=-30974,错误:DB_RUNRECOVERY: Fatal error, run database recovery.
[2014-07-21 00:47:20:314][线程2589176][5][20][0][]CBBoxPlugin::HandleInput_i 消息7:2801(source:1 26718,dest:1 10007)传输出现回路,丢弃此消息.

关于DB_RUNRECOVERY，此前研究过但没有深入，因为缺乏使之重现的手段。
http://pybsddb.sourceforge.net/api_c/env_set_paniccall.html中说内存不足可能导致此问题，先按此方向处理。

业务数据产生时间集中,数据量大,最大化并发,XML格式文件,32位程序，这些因素有可能造成内存紧张的情况.

如果确定DB_RUNRECOVERY是因为内存不足，考虑服务分离或升级到64位系统。

Windows系统内存限制的说明见:
Memory Limits for Windows and Windows Server Releases
http://msdn.microsoft.com/en-us/library/windows/desktop/aa366778%28v=vs.85%29.aspx

在x64平台上,Windows Server 2003 R2(sui_b本地服务器的运行环境)上运行32位程序，默认也只能使用2G内存。
使用更多内存需要启用/LARGEADDRESSAWARE链接选项。
http://msdn.microsoft.com/zh-cn/library/wz223b1z%28v=VS.90%29.aspx

2.2 jia_r日志分析

日志显示有(1)回路问题 (2)队列阻塞问题

2.2.1回路问题

[2014-07-21 00:10:23:049][线程2224][2][20][0][]CBBoxPlugin::HandleInput_i 处理消息6:809(source:3 0,dest:1 28342)...
[2014-07-21 00:10:23:049][线程2224][5][20][0][]CBBoxPlugin::HandleInput_i来自外部的非本地消息,转储文件:log\20140721001023_6_809_1_1.umx ret=0.
[2014-07-21 00:10:23:049][线程2224][1][20][0][]CBBoxPlugin::SendMsgToServer server ID=4146043...
[2014-07-21 00:10:23:049][线程2224][1][20][0][]CBBoxPlugin::SendMsgToServer server ID=4146043 ok.ret = -4.
[2014-07-21 00:10:23:049][线程2224][1][20][0][][thread 2224]file:e:\svn\供应宝\trunk\源代码\server\local_server\bbox\router.cpp line:592
[2014-07-21 00:10:23:049][线程2224][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 28342)传输出现回路,丢弃此消息.
[2014-07-21 00:10:23:049][线程2224][1][20][0][]************CBBoxPlugin::HandleInput_i()返回-7.
[2014-07-21 00:10:23:049][线程2224][1][20][0][][thread 2224]file:e:\svn\workdb\供应宝\hotfox\trunk\scheduler.cpp line:144
[2014-07-21 00:10:23:049][线程2224][2][20][0][](task_id=1)已处理消息6:809(priority:3),从(3:0)到(1:28342),包大小:130字节.处理结果:-7

所有回路（日志文件中有76次）都是同一源和目标的809-确认消息:

[2014-07-21 14:14:24:391][线程1356][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 28342)传输出现回路,丢弃此消息.

***这个现象和其它托管出现的产生umx文件是同一现象，此问题需要继续跟踪！！！

回路的规律如下：

[2014-07-21 13:30:23:102][线程3916][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 28342)传输出现回路,丢弃此消息.
[2014-07-21 13:41:23:396][线程3096][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 28342)传输出现回路,丢弃此消息.
[2014-07-21 13:52:23:327][线程1556][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 28342)传输出现回路,丢弃此消息.
[2014-07-21 14:03:23:632][线程2740][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 28342)传输出现回路,丢弃此消息.
[2014-07-21 14:14:24:391][线程1356][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 28342)传输出现回路,丢弃此消息.


[2014-07-21 14:03:22:960][线程3788][2][20][0][]default CSEMQ::Inquiry...
[2014-07-21 14:03:23:616][线程3788][2][20][0][]default CSEMQ::Inquiry 扫描记录数:1,处理记录数:1.
[2014-07-21 14:14:22:969][线程3788][2][20][0][]default CSEMQ::Inquiry...
[2014-07-21 14:14:24:376][线程3788][2][20][0][]default CSEMQ::Inquiry 扫描记录数:1,处理记录数:1.

从日志中可以看出每10分钟出现一次回路，可能是tb_0031中的同一记录。

日志摘录的后面部分是问询，每次只有这条记录。

意味者tb_0031中有一条目标为平台(dest_type=3,dest_id=0)，且源为机构28342的记录(src_type=1,src_id=28342)。

请检查tb_0031表，上述日志如果不出所料，应该每天都有。

这条记录是什么，什么时间生成的，怎么生成的？

类似的，还有12号托管.

[2014-07-21 09:35:59:675][线程4172][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 10028)传输出现回路,丢弃此消息.
[2014-07-21 09:35:59:675][线程4372][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 10028)传输出现回路,丢弃此消息.
[2014-07-21 09:35:59:675][线程2304][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 10028)传输出现回路,丢弃此消息.
[2014-07-21 09:35:59:675][线程4732][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 10028)传输出现回路,丢弃此消息.
[2014-07-21 09:35:59:706][线程2120][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 10028)传输出现回路,丢弃此消息.
[2014-07-21 09:48:11:003][线程4732][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 10028)传输出现回路,丢弃此消息.
[2014-07-21 09:48:11:034][线程4372][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 10028)传输出现回路,丢弃此消息.
[2014-07-21 09:48:11:034][线程2824][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 10028)传输出现回路,丢弃此消息.
[2014-07-21 09:48:11:534][线程5396][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 10028)传输出现回路,丢弃此消息.
[2014-07-21 09:48:11:534][线程6040][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 10028)传输出现回路,丢弃此消息.
[2014-07-21 09:57:59:081][线程3932][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 10028)传输出现回路,丢弃此消息.
[2014-07-21 09:57:59:144][线程5884][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 10028)传输出现回路,丢弃此消息.
[2014-07-21 09:57:59:269][线程5724][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 10028)传输出现回路,丢弃此消息.
[2014-07-21 09:57:59:347][线程4124][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 10028)传输出现回路,丢弃此消息.
[2014-07-21 09:57:59:378][线程4372][5][20][0][]CBBoxPlugin::HandleInput_i 消息6:809(source:3 0,dest:1 10028)传输出现回路,丢弃此消息.

[2014-07-21 09:46:59:050][线程4608][2][20][0][]default CSEMQ::Inquiry...
[2014-07-21 09:47:03:691][线程4608][2][20][0][]default CSEMQ::Inquiry 扫描记录数:52,处理记录数:5.
[2014-07-21 09:57:59:050][线程4608][2][20][0][]default CSEMQ::Inquiry...
[2014-07-21 09:57:59:472][线程4608][2][20][0][]default CSEMQ::Inquiry 扫描记录数:52,处理记录数:5.

上述日志显示有5条这样的记录。
tb_0031中存在目标为平台(dest_type=3,dest_id=0),源为机构10028的记录。

这是什么消息记录。

2.2.2队列阻塞问题

以下日志指示发送队列阻塞

[2014-07-21 14:12:37:342][线程3392][2][20][0][]CSEMQ::GetData 发送队列序号0, 队列个数32769.

出现后一直持续

[2014-07-21 03:08:53:570][线程2228][1][20][0][][thread 2228]file:e:\svn\供应宝\trunk\源代码\server\common\semq.cpp line:1595
[2014-07-21 03:08:53:570][线程2228][1][20][0][]CSEMQ::TraceAction acquire 1_1_1_250483...
[2014-07-21 03:12:21:449][线程2228][1][20][0][][thread 2228]file:e:\svn\供应宝\trunk\源代码\server\common\semq.cpp line:1601
[2014-07-21 03:12:21:449][线程2228][1][20][0][]CSEMQ::TraceAction ok,num of action_trace:1 .

阻塞发生在发送tb_0031数据的线程上.

原因可能是下面gyb优化事项(2)中流量控制的问题。
这些优化事项时在开发das过程发现的，一直未合并到gyb中。此次合并了其中的2项。

gyb优化事项(2)
http://blog.csdn.net/wherwh/article/details/26373695

gyb优化事项(1)

http://blog.csdn.net/wherwh/article/details/25918231

3.处理

.在trunk上重新编译bbox,ap插件.及BillCom相关模块.

.确认使用hotfox的版本为:\bin\release\hoard/hotfoxd.exe.

.全面升级sui_b和jia_r本地服务器(框架及所有插件)

.启用/3G(x86平台)

.bbox.conf的<water_mark>设置为-1

.删除ap.conf的<center_sock_buf_sizesend_buf="16384" recv_buf="16384"/>配置,采用默认配置(2M)