DAS连续测试下卡死问题

来源：互联网发布：知金教育招聘编辑：程序博客网时间：2024/05/29 15:09

1.问题

测试DAS时,如果bbox的参数按为方便快速调试调整参数(缩短间隔时间)后,出现发送端卡死的情况.

bbox.conf

<send_data_interval>3</send_data_interval><inquiry_timer_interval>60</inquiry_timer_interval><inquiry_interval>1</inquiry_interval><!--控制水位标.默认:300 -->    <water_mark>300</water_mark>     <!--活动跟踪超时值,单位:秒.默认:300 -->    <action_trace_timeout>300</action_trace_timeout>

调整参数后程序正常

<inquiry_timer_interval>60</inquiry_timer_interval><inquiry_interval>10</inquiry_interval><!--控制水位标.默认:300 -->    <water_mark>1000</water_mark>

分析5.24,5.25,5.26的日志:

[2014-05-26 00:01:47:558][线程8584][2][20][0][]CConnectorEventTask::handle_message_block() Event=2,info_flag=114.msg_count=0.[2014-05-26 00:01:47:558][线程8584][5][20][0][]Sock_Handler::start_write.队列个数：6445.[2014-05-26 00:01:47:558][线程8584][2][20][0][]CConnectorEventTask::handle_message_block() Event=2 ok.[2014-05-26 00:01:47:558][线程8584][2][20][0][]CConnectorEventTask::handle_message_block() Event=2,info_flag=114.msg_count=0.[2014-05-26 00:01:47:558][线程8584][5][20][0][]Sock_Handler::start_write.队列个数：6446.

发送队列出现堆积.

[2014-05-25 21:51:47:560][线程472][1][20][0][][thread 472]file:e:\svn\das\trunk\ls\server\common\semq.cpp line:1659[2014-05-25 21:51:47:560][线程472][1][20][0][]CSEMQ::handle_timeout ok,num of action_trace:300 .[2014-05-25 21:52:47:558][线程472][1][20][0][][thread 472]file:e:\svn\das\trunk\ls\server\common\semq.cpp line:1659[2014-05-25 21:52:47:558][线程472][1][20][0][]CSEMQ::handle_timeout ok,num of action_trace:300 .

流量控制出现堆积和超时.(消息返回不及时)

[2014-05-25 11:14:47:836][线程1068][2][20][0][]接收到消息(6:809,S=8:0,D=1:10600,cmdserial=0),进入处理队列1,队列元素个数为32768...[2014-05-25 11:14:47:836][线程1068][1][20][0][][thread 1068]file:e:\svn\workdb\供应宝\hotfox\trunk\task.cpp line:109[2014-05-25 11:14:47:836][线程1068][1][20][0][]HTX_Task_Base(HTX_Scheduler)队列元素个数=32769.

HTX_Scheduler队列1出现阻塞。

默认队列大小（字节数）
const unsigned long DEFAULT_QUEUE_WATER_MARK = 128*1024;

每个元素存放的是4字节指针，所以最大元素个数为32k字节

HTX_Dispatcher_Task也出现阻塞：

[2014-05-25 21:50:48:093][线程4204][1][20][0][][thread 4204]file:e:\svn\workdb\供应宝\hotfox\trunk\sockhandler.cpp line:597[2014-05-25 21:50:48:093][线程4204][1][20][0][]Sock_Handler::handle_read_stream socket=3988 channel=1...[2014-05-25 21:50:48:093][线程4204][1][20][0][][thread 4204]file:e:\svn\workdb\供应宝\hotfox\trunk\task.cpp line:94[2014-05-25 21:50:48:093][线程4204][1][20][0][]HTX_Task_Base(HTX_Dispatcher_Task)队列元素个数=32769.

最后会导致通信阻塞.

start_write的原因是通信阻塞，通信阻塞是因为HTX_Dispatcher_Task阻塞，HTX_Dispatcher_Task阻塞是因为HTX_Scheduler阻塞。

HTX_Scheduler阻塞是因为处理：809-Confirmation消息。
---处理消息没有结束
线程8676在5.24日就已经阻塞！！！

 [2014-05-24 18:25:48:451][线程4112][1][20][0][]CSEMQ::ActionAck 2_1_1_116855...[2014-05-24 18:25:48:451][线程8676][4][20][0][]接收到809确认[semq_id:1,semq_db_id:1,ref_id:116861,result:1][2014-05-24 18:25:48:451][线程8676][1][20][0][][thread 8676]file:e:\svn\das\trunk\ls\server\common\semq.cpp line:1641[2014-05-24 18:25:48:451][线程8676][1][20][0][]CSEMQ::ActionAck 2_1_1_116861...

这是8676线程最后输出的日志。
从数据库连接使用情况看，该线程占用了第35个连接，一直没有释放（包括到5.25,5.26的日志）
可见，阻塞在处理809-Confirmation消息上.
result=1,表示是成功的确认。

2.代码分析

问题应该出在下面的代码中(注意:ack=1----result的值为ack).
且注意并没有阻塞在CSEMQ::ActionAck中。（从其函数实现代码分析得出，只有action_trace_涉及锁，该对象在后来有被一直使用）。

***下面的代码，缺少精确定位的日志。只能借助逻辑分析
----肯定是得到了数据库连接（此前该线程没有获取连接），

***增加日志，以便内部测试时验证分析！！！

int CBBoxPlugin::OnRespInquiry(CWrappedMsg<> *in,vector<CWrappedMsg<> *> &out,DISPATCH_RESULT &or) {

       CSEMQItem qe;
       int iRet = semq_.GetItem(qe, 0,0,ref_object_id);
       if(iRet < 0)
       {
           //pdbor->RollbackTrans();
           return -3;
       }
       if(iRet == 1)
       {
           GETDBC_RETURN(pdbor,this->local_dbc_.c_str(),-1); ///< @分析这里获取的连接
           pdbor->BeginTrans();
           result = semq_.UpdateStatus(ref_object_id,ISEMQ::SS_ACK2);
           if(result)
           {
               pdbor->RollbackTrans(); ///@分析没有从此处退出
               return -2;
           }
           if (!qe.sc_key_.empty()) { ///< @分析肯定是有时序控制的(如果确认的是单据消息，目前应该全部是单据消息)
               CQQ_OBJECT_ID next_object_id=qe.object_id_;
               int ret = semq_.GetNextSeqCtrlRecord(qe.sc_key_.c_str(),next_object_id);
               if (ret==1) {
                   pdbor->SetTXHook(TxHook,&semq_); /// @分析事务挂钩. 把下一个相同时序控制键的记录执行发送
                   semq_tss_->v_rec.push_back(new SEMQ_RECORD_DATA_PAIR(next_object_id, qe.sc_key_));
               }
               else if (ret==-1) {
                   pdbor->RollbackTrans();
                   return -3;
               }
           }
           /// @分析只有lm处理DATA_SEND_OUT事件，来修改单据表中单据的状态。调用 pSheet->UpdateSendStatus。
           /// 该方法执行的就是SQL update语句。不应该阻塞在此。

           if (!ISEMPTY_STR(qe.ref_key_.c_str())) {
               vector<string> vs;
               if (SplitString(qe.ref_key_.c_str(), vs) >= 2) {///< 应用关联键的格式:域,数据类型,子类型,记录定位键.其中域,数据类型是必须的
                   ///< 产生数据发送事件
                   CDataSendoutEvent *e = new CDataSendoutEvent;
                   e->data_type_ = atoi(vs[1].c_str()); ///< 数据类型
                   e->sub_type_ = ISEMQ::SS_ACK2; ///< 状态作为子类型
                   const int kLen = 33;
                   char sz_orgid[kLen];
                   ltoa(qe.src_id_,sz_orgid,10);
                   e->ref_ = qe.ref_key_ + "," ;
                   e->ref_ += sz_orgid;
                   e->dest_t_ = qe.dest_type_;
                   e->dest_id_ = qe.dest_id_;
                   e->send_time_ = qe.send_time_;
                   ///< 激发事件
                   if (event_controller_->pulse(DATA_SEND_OUT,e)) { ///< 激发事件失败,事务回滚
                       pdbor->RollbackTrans();
                       return -4;
                   }
               }
           }
           FAIL_RETURN(pdbor->CommitTrans(),,-1);
           ///< @分析这里提交，提交后会执行TxHook中的
           ///            semq->SendRecord(data->object_id);

****问题应该出现在以下环节：（测试后跟踪）

int CSEMQ::SendRecord(CQQ_OBJECT_ID object_id) {
   CSendTaskItem *sti = new CSendTaskItem;
   sti->action_ = 1;
   sti->type_ = 1;
   sti->object_id_ = object_id;
   ACE_Message_Block *mb = 0;
   ACE_NEW_RETURN(mb,ACE_Message_Block(sizeof(CSendTaskItem*)),-1);
   memcpy(mb->rd_ptr(),&sti,sizeof(CSendTaskItem*));
   pre_send_task_.putq(mb); ///< @分析 pre_send_task_阻塞了？
   return 0;
}

pre_send_task_的主要处理如下
int CSEMQ::GetData(string &sql) {

       int cnt = send_task_[st_index].putq(mb);
       if(cnt > 100)
           GetLogger()->log(LO_STDOUT|LO_FILE,SEVERITY_INFO,"CSEMQ::GetData 发送队列序号%d, 队列个数%d\n",
           st_index,cnt);

[2014-05-24 18:25:48:030][线程6428][2][20][0][]CSEMQ::GetData扫描记录数:0,发送记录数:0.耗时:0.00秒
[2014-05-24 18:25:48:030][线程6428][2][20][0][]CSEMQ::GetData... ///< 此函数在当天5.24日的日志中没有结束信息（如上内容）

而6428的线程当天最后的日志如下：

[2014-05-24 23:59:47:575][线程6428][2][20][0][]CSEMQ::GetData 发送队列序号0, 队列个数32769

在第2天(5.25日)中该线程的活动有：
[2014-05-25 00:31:48:017][线程6428][2][20][0][]CSEMQ::GetData扫描记录数:3389,发送记录数:3385.耗时:21959.99秒
[2014-05-25 00:31:48:017][线程6428][2][20][0][]CSEMQ::GetData...

从5.24到5.25之间耗时6多个小时（21959秒，与日志输出时间相当）----每条记录处理时间:6秒。

表示pre_send_task_任务阻塞了6个小时!!!

[2014-05-24 18:26:47:559][线程6428][2][20][0][]CSEMQ::GetData 发送队列序号0, 队列个数32769[2014-05-24 23:59:47:575][线程6428][2][20][0][]CSEMQ::GetData 发送队列序号0, 队列个数32769

---虽然队列元素满，但一直在执行，并未卡死。

send_task_(CSEMQSendTask)

///< 负责把消息队列的元素发送出去int CSEMQSendTask::handle_message_block(ACE_Message_Block *mb) {    SHORT_SEMQ_RECORD *ssr = 0;    memcpy(&ssr, mb->rd_ptr(), sizeof(SHORT_SEMQ_RECORD*));    mb->rd_ptr(sizeof(SHORT_SEMQ_RECORD*));    int result = this->semq_->Proc(ssr);    delete ssr;    return result;}int CSEMQ::Proc(SHORT_SEMQ_RECORD *ssr) {    GetLogger()->log(LO_STDOUT|LO_FILE,SEVERITY_DEBUG,"CSEMQ::Proc,dest_type=%d,dest_id=%d...\n",ssr->dest_type_,ssr->dest_id_);    int ret = Send(ssr);    GetLogger()->log(LO_STDOUT|LO_FILE,SEVERITY_DEBUG,"CSEMQ::Proc结束.ret=%d.\n",ret);    return ret;}

[2014-05-24 23:59:47:575][线程4772][1][20][0][]CSEMQ::Send 结束.is_ok=1.耗时:0.01秒.[2014-05-24 23:59:47:575][线程4772][1][20][0][]CSEMQ::Proc结束.ret=0.

说明send_task_一直在执行，没有卡死。

彻底阻塞应该是CSEMQ::SendRecord调用处产生的。

但目前无法解释.

3.后续跟踪

下次出现时，检查日志中以下内容：
增加日志输出内容：
(1)CBBoxPlugin::OnRespInquiry
               int ret = semq_.GetNextSeqCtrlRecord(qe.sc_key_.c_str(),next_object_id);
               GetThisLogger()->log(LO_STDOUT|LO_FILE,SEVERITY_DEBUG,"取下一个相同时序键%s的记录.qe.object_id=%I64d,next_object_id=%I64d,ret=%d.\n",
                   qe.sc_key_.c_str(),qe.object_id_,next_object_id,ret);

(2)CSEMQ::SendRecord
int CSEMQ::SendRecord(CQQ_OBJECT_ID object_id) {
   GetLogger()->log(LO_STDOUT|LO_FILE,SEVERITY_DEBUG,"CSEMQ::SendRecord(object_id=%I64d)...\n",object_id);

   CSendTaskItem *sti = new CSendTaskItem;
   sti->action_ = 1;
   sti->type_ = 1;
   sti->object_id_ = object_id;
   ACE_Message_Block *mb = 0;
   ACE_NEW_RETURN(mb,ACE_Message_Block(sizeof(CSendTaskItem*)),-1);
   memcpy(mb->rd_ptr(),&sti,sizeof(CSendTaskItem*));
   int cnt = pre_send_task_.putq(mb);
   GetLogger()->log(LO_STDOUT|LO_FILE,SEVERITY_DEBUG,"CSEMQ::SendRecord ok.pre_send_task队列元素个数:%d.\n",cnt);

   return 0;
}

0 0