1.服务器
1.1日志分析
现象1:tb_1045主键冲突
[2014-12-01 05:00:38:425][线程7188][2][20][0][]CBBoxPlugin::HandleInput_i 处理消息7:2800(source:1 10009,dest:8 0)...
[2014-12-01 05:00:38:441][线程7188][1][20][0][]************CBBoxPlugin::HandleInput_i()返回0.
[2014-12-01 05:00:38:441][线程7188][2][20][0][]正在处理:接收发送队列数据协议(7:2800,S=1:10009,D=8:0,cmdserial=0)...
[2014-12-01 05:00:38:441][线程7188][4][20][0][]接收到2800[,,,,1045,0100,10009]
[2014-12-01 05:00:38:441][线程7188][1][20][0][]正在处理机构10009的单据0100...
[2014-12-01 05:00:38:441][线程7188][5][20][0][]CDbAccessor2::Execute insert into tb_1045(ORGID,F001V_1045,F002V_1045,F003V_1045,STATUS,MODIFY_TIME) values (10009,'0100','配送中心','深圳市宝安区沙井镇芙蓉工业区芙蓉三路',0,'2014-12-01 05:00:01');产生异常(Error
Code = 80040e2f
Code meaning = IDispatch error #3119
Source = Microsoft OLE DB Provider for SQL Server
Description =违反了 PRIMARY KEY 约束 'PK_tb_1045'。不能在对象 'dbo.tb_1045' 中插入重复键。
([1]Number:0X80040E2F Description:违反了 PRIMARY KEY 约束 'PK_tb_1045'。不能在对象 'dbo.tb_1045' 中插入重复键。 SQLState:23000 NativeError:2627[2]Number:0X80040E2F Description:语句已终止。 SQLState:01000 NativeError:3621)).
[2014-12-01 05:00:38:441][线程7188][1][20][0][]CDxkChangeLog::HandleBillAccept...
[2014-12-01 05:00:38:441][线程7188][1][20][0][]HandleLogRecord正在处理:sheet_type=1045,rule_id=1045,app_pk=F001V_1045=C[0100]...
[2014-12-01 05:00:38:441][线程7188][1][20][0][]CTask::Run ...
[2014-12-01 05:00:38:441][线程7188][1][20][0][]执行GetData...
[2014-12-01 05:00:38:456][线程7188][1][20][0][]CTask::GetData 耗时0.02秒.
[2014-12-01 05:00:38:456][线程7188][4][20][0][]没有查找到数据.
[2014-12-01 05:00:38:456][线程7188][1][20][0][]CDxkChangeLog::HandleBillAccept ok.
这里有2个问题(1)tb_1045主键冲突 (2)没有查找到数据(都提示冲突了怎么会找不到数据呢)
(1)tb_1045主键冲突时因为每日全部重传门店资料。出现此错误时会根据主键冲突处理方式自动处理,如进行更新。
出现此错误属于正常情况。
主键冲突处理方式配置
lm.conf
<on_duplicate_key> <!-- 主键冲突处理方式 忽略-1,继续尝试-2,更新-3 默认:3 -->
(2)没有查找到数据:是会因为配置错误,导致执行的查询不是预期的
[2014-12-01 05:00:38:456][线程7188][4][20][0][]没有查找到数据.
执行的sql是:
select
bizcode as bizstoreid,
f001v_1045 as shopid,
f002v_1045 as name,
f003v_1045 as address,
provincename as provincename,
cityname as cityname,
status as status,
opendate as opendate,
closedate as closedate
from tb_1045 a,tb_jxjorgcode b
where f001v_1045='0100' and a.orgid=10007
and a.orgid=b.orgid
门店的信息是10009的,但查询时10007的。
现象2:tb_0045错误的删除
[2014-12-01 06:01:33:144][线程2900][5][20][0][]CDbAccessor2::Execute delete from tb_1045 where F001V_1045='Y003'产生异常(Error
Code = 80004005
Code meaning = 未指定的错误
Source = Microsoft OLE DB Provider for SQL Server
Description =事务(进程 ID 57)与另一个进程被死锁在 锁 资源上,并且已被选作死锁牺牲品。请重新运行该事务。
([1]Number:0X80004005 Description:事务(进程 ID 57)与另一个进程被死锁在 锁 资源上,并且已被选作死锁牺牲品。请重新运行该事务。 SQLState:40001 NativeError:1205)).
[2014-12-01 06:01:33:144][线程2900][2][20][0][]"接收发送队列数据协议"(2800,cmdserial=0)处理完成,返回值:-1,结果消息个数:0
语句
delete from tb_1045 where F001V_1045='Y003'
有逻辑错误。
门店是零售商自行编码的,必须用orgid,f001v_1045唯一区分。否则,2个零售商门店编码(f001v_1045)相同时会导致破坏数据。
****调整配置(tb_1031及抽取)
正确的语句应当如下:
delete from tb_1045 where F001V_1045='Y003' and orgid=?
---利用索引可以降低死锁几率
现象3:tb_0030主键冲突
[2014-12-01 07:06:28:659][线程7276][2][20][0][]CBBoxPlugin::HandleInput_i 处理消息7:2800(source:1 10009,dest:8 0)...
[2014-12-01 07:06:28:659][线程7276][1][20][0][]************CBBoxPlugin::HandleInput_i()返回10.
[2014-12-01 07:06:28:659][线程7276][5][20][0][]CDbAccessor2::Execute insert into TB_0030(src_type,src_id,dest_type,dest_id,f003v_0030,f005d_0030) values(1,10009,8,0,'1,10009,1,1,224739','2014-12-01 07:06:28')产生异常(Error
Code = 80040e2f
Code meaning = IDispatch error #3119
Source = Microsoft OLE DB Provider for SQL Server
Description =不能在具有唯一索引 'ui_0030_2' 的对象 'dbo.TB_0030' 中插入重复键的行。
([1]Number:0X80040E2F Description:不能在具有唯一索引 'ui_0030_2' 的对象 'dbo.TB_0030' 中插入重复键的行。 SQLState:23000 NativeError:2601[2]Number:0X80040E2F Description:语句已终止。 SQLState:01000 NativeError:3621)).
[2014-12-01 07:06:28:659][线程7276][2][20][0][]CBBoxPlugin::HandleSend 处理消息7:810(source:8 0,dest:1 10009)...
[2014-12-01 07:06:28:659][线程7276][1][20][0][]ConnectorEventInfo消息队列个数:1.
[2014-12-01 07:06:28:659][线程7276][1][20][0][][thread 7276]file:e:\svn\workdb\供应宝\hotfox\trunk\scheduler.cpp line:144
[2014-12-01 07:06:28:659][线程7276][2][20][0][](task_id=27)已处理消息7:2800(priority:1),从(1:10009)到(8:0),包大小:2675字节.处理结果:10
ui_0030_2是建立在f003v_0030(确认记录键)上的唯一索引.b_0030是不应该有插入f003v_0030重复记录的情况.
int CBBoxPlugin::HandleInput(CWrappedMsg<> *pwm,void **pploc,int &action) {
int ret = -1;
try {
CMsg *msg = pwm->GetMsg();
bool do_ack = msg->IsAutoAck(); ///< 包含msg->IsAck2
ret = HandleInput_i(pwm,pploc,action);
nlogger_->log(LO_STDOUT|LO_FILE,SEVERITY_DEBUG,"************CBBoxPlugin::HandleInput_i()返回%d.\n",ret);
/// ret: 0-交给插件处理 其它值:错误 (<0)或者转发(>0)
SEMQ_ACK_HELPER *ah = (SEMQ_ACK_HELPER*)*pploc;
if (action&&do_ack) {
if (action==-1)
semq_.Ack(ah,1);
else {
///< @note 如果tb_0030已经接收到则不应该再insert
if (semq_.SaveAck(ah)==0) ///< @note 写入后loc中保存semq的object_id信息,Ack时需要使用
semq_.Ack(ah,0);
}
}
if (ret) { /// ret==0表示交给插件处理,其它值时释放ah对象
if (ah) {
delete ah;
*pploc = 0;
}
}
} catch(...) {
nlogger_->log(LO_STDOUT|LO_FILE,SEVERITY_ERROR,"************CBBoxPlugin::HandleInput()异常.\n");
}
return ret;
}
action参数含义:
0--不确认
1-成功确认
-1-失败确认:失败确认可能是需要重传的,取决于是否自动挂起和失败次数
目前action=-1未被使用。
在增加了失败重做特性后,失败确认已经无意义,SEMQ只负责传输,不关心消息处理是否成功。
调整:
3-不写tb_0030但要确认
对于CheckAck已经确认接收到的消息,不需要再写tb_0030,直接返回确认消息。
不按位定义action,是为了减少代码改动
修改后:
if (action&&do_ack) {
if (action==-1)
semq_.Ack(ah,1);
else {
if (action==3||semq_.SaveAck(ah)==0)
semq_.Ack(ah,0);
}
}
int CBBoxPlugin::HandleInput_i(CWrappedMsg<> *pwm,void **pploc,int &action)
{
SEMQ_ACK_HELPER* loc = GenAckHelper(pwm);
*pploc = loc;
action = 1; ///< 是否需要确认检查 1-需要 0-不需要 实际上是否确认是HandleInput函数中由msg->IsAutoAck()控制
...
CMsg *msg = pwm->msg;///pwm->Detach();
if (loc&&msg->IsAutoAck()) { ///< 检查是否是重复发送的消息(需要确认的消息接收后会写入Ack队列)
int ret = CheckAck(loc);
if (ret==-1) {
action = 0;
return -10;
}
if (ret==1) {
action = 3; ///< 不写tb_0030 ///< @note 新增此行代码
return 10;
}
}
已同时修改以下3个项目的代码
.das 1.0
.gyb trunk
.gyb2
dxi_ddd.conf配置错误
dxi_ddd.conf关于门店的规则配置存在以下问题:
---<key_field>缺少orgid字段。
---<command>的配置中orgid=10007,不应该是固定的常量,应该用@orgid的形式
实际配置如下:
<rule>
<!--门店规则ID,自己定义要与dxi_change_log对应好 -->
<id>1045</id>
<!--单据类型,可以到0044表中查询获取-->
<data_type>1045</data_type>
<!--源主表主键-->
<src_db>
<ds_name>laton</ds_name> <!--源表数据源名称,缺省为默认源数据源 -->
<master_table_name>tb_1045</master_table_name> <!-- 源表中主表名称,具体情况看抽取的sql,可能是从表(例如销售库存)不通过data_type自动获取是避免依赖,此模块可独立使用,不需要单据类型信息支持 -->
<key_field>f001v_1045</key_field> <!--主表字段名称列表,会自动带入job表中的app_pk字段中内容到最下面的sql中 @ @内容 -->
</src_db>
<dest_db>
<ds_name>JXJ_DB</ds_name> <!--目标数据源名称,缺省为默认目标数据源-->
<master_table_name>tsm_shop_jk</master_table_name> <!-- 目标主表名称,仅用于业务主键冲突时删除原数据-->
<key_field prop="0">shopid</key_field> <!--prop表示属性 bit0: 1表示是自增长字段,注意填写导入目标表中的主键,需要填写目标表中的字段名-->
</dest_db>
<tables><!--表映射 -->
<table>
<name>tsm_shop_jk</name><!--目标主表名 -->
<command>
select
bizcode as bizstoreid,
f001v_1045 as shopid,
f002v_1045 as name,
f003v_1045 as address,
provincename as provincename,
cityname as cityname,
status as status,
opendate as opendate,
closedate as closedate
from tb_1045 a,tb_jxjorgcode b
where f001v_1045='@f001v_1045' and a.orgid=10007
and a.orgid=b.orgid
</command>
</table>
</tables>
</rule>
1.2处理意见
.修改dxi_ddd.conf配置---解决现象1的问题
.门店资料表字典信息增加orgid作为主键列,修改抽取规则.---解决现象2的问题
.编译升级bbox---解决现象3的问题,暂时不升级
2.前置机
2.1分析
现象1:tb_1045主键冲突
这是由于门店抽取每天全量处理,抽取的记录写入本地时报此错误。
[2014-11-30 06:01:21:675][线程1624][5][20][0][]CDbAccessor2::Execute insert into tb_1045(ORGID,F001V_1045,F002V_1045,F003V_1045,STATUS,MODIFY_TIME) values (10047,'F096','华冠欢乐城店','11',0,'2014-11-30 05:54:41');产生异常(Error
Code = 80040e2f
Code meaning = IDispatch error #3119
Source = Microsoft OLE DB Provider for SQL Server
Description =违反了 PRIMARY KEY 约束 'PK_tb_1045'。不能在对象 'dbo.tb_1045' 中插入重复键。
([1]Number:0X80040E2F Description:违反了 PRIMARY KEY 约束 'PK_tb_1045'。不能在对象 'dbo.tb_1045' 中插入重复键。 SQLState:23000 NativeError:2627[2]Number:0X80040E2F Description:语句已终止。 SQLState:01000 NativeError:3621)).
主键冲突时会按照lm.conf的<on_dup_key>的配置处理。
此错误不影响正常运行。
如果升级到das2.0,把抽取规则配置为全表同步,则可以消除此错误。
现象2:系统忙时,经常出现无可用数据库连接的情况:
[2014-11-30 07:28:48:159][线程888][2][20][0][]LATON#client使用情况:
[2014-11-30 07:28:48:159][线程888][2][20][0][][1]连接id=1,使用状态=已使用,取用时间=5255(秒),拥有者线程=3184.
配置的数据库连接数为35个。
这和数据库性能低下有关。也可以加大hotfox.conf的数据库连接配置,该值一般应设置的比<scheduler><thread>大。
现象3:大量的频繁的“超时已过期”的错误
[2014-11-30 10:45:42:362][线程1056][5][20][0][]CDbAccessor2::Execute update tb_1050 set send_status = 100, send_time = '2014-11-30 10:35:41' where sheet_id = 'F076201411290021' and src_orgid = 10047产生异常(Error
Code = 80040e31
Code meaning = IDispatch error #3121
Source = Microsoft OLE DB Provider for SQL Server
Description =超时已过期
([1]Number:0X80040E31 Description:超时已过期 SQLState:HYT00 NativeError:0)).
[2014-11-30 10:45:42:362][线程1056][5][20][0][]DATA_SEND_OUT事件处理失败,UpdateSheetTableStatus=-1,键=0,100,1050,10047,F076201411290021,10047
sql命令耗时情况:
[2014-11-30 06:01:04:769][线程2992][2][20][0][]select 10047 as storeid, a.sheetid, a.venderid, a.shopid, a.refsheetid, 1 as status, convert(char(10) ,a.checkdate,120) as checkdate, b.deptid, sum(b.qty*b.cost) costvalue, convert(char(10) ,a.checkdate,120) as checkdate1 from ret a,retcostitem b where a.sheetid=b.sheetid and a.flag=100 and convert(char(10) ,checkdate,120) between convert(char(10) ,getdate() -3,120) and convert(char(10) ,getdate() -1,120) group by a.sheetid,a.refsheetid,a.shopid,a.venderid,a.flag,convert(char(10) ,a.checkdate,120) ,b.deptid
耗时:21.20(秒)
[2014-11-30 06:01:42:581][线程2920][2][20][0][]update tb_1105 set send_status = 4, send_time = '2014-11-30 06:01:25' where sheet_id = 'F086201411290003' and src_orgid = 10047
耗时:17.25(秒)
[2014-11-30 06:12:21:269][线程908][2][20][0][]update tb_1050 set send_status = 100, send_time = '2014-11-30 06:02:20' where sheet_id = 'F085201411290003' and src_orgid = 10047
耗时:600.33(秒)
[2014-11-30 06:12:21:284][线程1048][2][20][0][]update tb_1050 set send_status = 100, send_time = '2014-11-30 06:02:21' where sheet_id = 'F087201411290085' and src_orgid = 10047
耗时:600.23(秒)
[2014-11-30 06:23:05:034][线程1316][2][20][0][]update tb_1101 set send_status = 100, send_time = '2014-11-30 06:13:05' where sheet_id = 'F029201411290014' and src_orgid = 10047
耗时:599.97(秒)
[2014-11-30 06:33:06:097][线程3424][2][20][0][]update tb_1101 set send_status = 100, send_time = '2014-11-30 06:23:07' where sheet_id = 'F092201411280005' and src_orgid = 10047
耗时:598.83(秒)
[2014-11-30 06:33:18:644][线程3200][2][20][0][]update tb_1050 set send_status = 100, send_time = '2014-11-30 06:33:05' where sheet_id = 'F061201411290023' and src_orgid = 10047
耗时:12.72(秒)
[2014-11-30 06:44:43:722][线程1316][2][20][0][]update tb_1101 set send_status = 100, send_time = '2014-11-30 06:34:43' where sheet_id = 'F086201411280008' and src_orgid = 10047
耗时:600.38(秒)
2.2处理意见
1.大量的频繁的超时已过期的错误:(1)检查数据库服务器硬件配置 (2)进行优化
2.系统忙时,经常出现无可用数据库连接的情况。配置的数据库连接数为35个。
这和数据库性能低下有关。也可以加大hotfox.conf的数据库连接配置,该值一般应设置的比<scheduler><thread>大。