如何找bug

将发送端sleep时间定为0， 即sleep(0).

事例率也在700Hz持续3分钟后降为0.查看log文件：

1. SFI 的log文件：

WARNING 2017-Feb-08 15:39:55 [DC::StatusWord EventAssembly::EventCompleted(...) at SFI/src/EventAssembly.cxx:480] Problem with the flow of data: Event with LVL1ID 130745 misses 1 data fragment(s) from: ROS-Eth-07,
WARNING 2017-Feb-08 15:39:55 [DC::StatusWord EventAssembly::EventCompleted(...) at SFI/src/EventAssembly.cxx:480] Problem with the flow of data: Event with LVL1ID 130749 misses 1 data fragment(s) from: ROS-Eth-07,
WARNING 2017-Feb-08 15:39:55 [DC::StatusWord EventAssembly::EventCompleted(...) at SFI/src/EventAssembly.cxx:480] Problem with the flow of data: Event with LVL1ID 130753 misses 1 data fragment(s) from: ROS-Eth-07,

2. ROS 的log文件：

Warning could not load libEthClientSequentialReadoutModule.so, trying libROSEthClientSequentialReadoutModule.so
ERROR 2017-Feb-08 15:44:10 [virtual void ROS::RequestHandler::run(...) at ROSCore/src/RequestHandler.cpp:274] Unclassified error: RequestHandler caught exception, deleting Request
was caused by: ERROR 2017-Feb-08 15:44:10 [unknown at unknown:0] No pages available

找到ROSCore/src/RequestHandler.cpp:274:

  catch (std::exception& issue) {
274          ENCAPSULATE_ROS_EXCEPTION(newIssue, CoreException, UNCLASSIFIED, issue, "RequestHandler caught exception, deleting Request    ");  
275          ers::error(newIssue);
276          deleteRequest();
277       }

先找到 ENCAPSULATE_ROS_EXCEPTION的定义：并没有看出啥，只看出来例外的类型是CoreException, errorCode是UNCLASSIFIED.

/** def ENCAPSULATE_ROS_EXCEPTION(instanceName, exceptionClass, errorCode, oldException, messageContent)
    Macro to encapsulate an exception inside a ROSException along with
    some explanatory text.
*/
#define ENCAPSULATE_ROS_EXCEPTION(instanceName, exceptionClass, errorCode, oldException, messageContent) 
    std::ostringstream instanceName##_tStream; 
    instanceName##_tStream << messageContent; 
    exceptionClass instanceName(oldException, exceptionClass::errorCode, instanceName##_tStream.str(), ERS_HERE)

#endif

然后再查看try里面的语句

243       try {
244          TS_RECORD(TS_H1,stamp_offset + 2100);
245          int requestOk;
246          //unsigned int tsdata = m_handlerId * 100 + 3000000000;
247          //TS_RECORD(TS_H5,tsdata);
248 
249          requestOk = m_request->execute();
250          TS_RECORD(TS_H1,stamp_offset + 2200);
251 
252          if (requestOk == Request::REQUEST_OK) {
253             m_requestsHandled++;
254             deleteRequest();
255             TS_RECORD(TS_H1, stamp_offset + 2300);
256          }
257          else if (requestOk == Request::REQUEST_TIMEOUT) {
258             m_requestsTimedOut++;
259             deleteRequest();
260             TS_RECORD(TS_H1, stamp_offset + 2300);
261          }
262          else {
263             TS_RECORD(TS_H1, stamp_offset + 2400);
264             DEBUG_TEXT(DFDB_ROSCORE, 15, "RequestHandler(" << m_handlerId <<")::run: Request non completed: will be requeued.");
265             m_requestsFailed++;
266       m_request = m_requestQueue->swap(m_request);
267             DFThread::yieldOrCancel();
268             TS_RECORD(TS_H1, stamp_offset + 2500);
269          }
270 
271          TS_RECORD(TS_H1, stamp_offset + 2990);
272       }

整个try...catch语句是在requesthandler的run函数里面，run函数是requesthandler的执行线程，从request queue里面拿出一个request, 执行这个request，然后再删除这个request.

通过加打印得到：try语句里执行了第一个if语句，证明request被执行后返回了REQUEST_OK，在执行if内部的语句deleteRequest();时，出现了例外。

再查看deleteRequest（）函数里面写了什么：

193 void RequestHandler::deleteRequest()
194 {
195   if (m_request != 0) {
197     m_mutex->lock() ;   // Memory deallocation has to be protected as
198        delete(m_request);    // it is thread-unsafe!
199        m_request=0;
200        m_mutex->unlock();
201    }
202 }

在 if 里面每条语句里面加打印，在requesthandler的析构函数里面加打印，并查看log文件

void RequestHandler::deleteRequest()
194 {
195   if (m_request != 0) {
196     std::cout << "m_request is not 0:1!" << std::endl;
197     m_mutex->lock() ;   // Memory deallocation has to be protected as
198     std::cout << "m_request is not 0:2!" << std::endl;
199     delete(m_request);    // it is thread-unsafe!
200     std::cout << "m_request is not 0:3!" << std::endl;
201     m_request=0;
202     std::cout << "m_request is not 0:4!" << std::endl;
203     m_mutex->unlock();
204     std::cout << "m_request is not 0:5!" << std::endl;
205   }
206 }

查看ROS-Eth-04的log文件，发现：

[lhaaso@cmm03node01 part_dk_ef]$ grep "m_request is not 0:1" ROS-Eth-04_cmm03node01_1486545277.out |wc -l
261133
[lhaaso@cmm03node01 part_dk_ef]$ grep "m_request is not 0:2" ROS-Eth-04_cmm03node01_1486545277.out |wc -l
261239

[lhaaso@cmm03node01 part_dk_ef]$ grep "~Request" ROS-Eth-04_cmm03node01_1486545277.out |wc -l
130624
[lhaaso@cmm03node01 part_dk_ef]$ grep "m_request is not 0:3" ROS-Eth-04_cmm03node01_1486545277.out |wc -l
261239
[lhaaso@cmm03node01 part_dk_ef]$ grep "m_request is not 0:4" ROS-Eth-04_cmm03node01_1486545277.out |wc -l
261239
[lhaaso@cmm03node01 part_dk_ef]$ grep "m_request is not 0:5" ROS-Eth-04_cmm03node01_1486545277.out |wc -l
261238

这几条语句的执行次数，发现deleteRequest操作的次数比其前后打印的次数要少很多，证明有很多次delteRequest并没有成功，抛出例外，并导致程序报错了。

 (批注:实际上是Request有两个子类，FragmentRequest 和 ReleaseFragment类, RequestHandler执行的时候根据收到SFI的消息种类判断执行哪一种Request。)