das系统检查记录（2014.12.04）

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>大。