僵死的任务对应的规则:规则8,规则111705。任务号(task_id):2.
1.分析
扫描线程为:9668[2014-10-13 20:26:13:556][线程9668][2][20][0][]DeamonTask[CDxkChangeLog::ChangeLogScanProc::2,线程数:1]:正在执行...
处理线程为:25672
[2014-10-13 18:50:46:284][线程25672][1][20][0][]HandleLogRecord正在处理:sheet_type=88,rule_id=111705,app_pk=C_ID=C[1-146-1132]...
目前分析得到的信息有:
(1)曾出现MySQL,Oracle连接不上的情况,但最终能恢复,所以不是数据库不可用的问题
(2) 从现象看是扫描线程阻塞.
任务扫描线程最后执行的时间为:
[2014-10-13 20:26:13:556][线程9668][2][20][0][]DeamonTask[CDxkChangeLog::ChangeLogScanProc::2,线程数:1]:正在执行...
且没有表示结束的类似下面的日志信息:
[2014-10-13 20:18:41:016][线程9668][2][20][0][]DeamonTask[CDxkChangeLog::ChangeLogScanProc::2,线程数:1]:执行完毕,返回码=0.
这说明ChangeLogScanProc没有执行结束,阻塞在某处了。
由于扫描线程没有结束,没有新的记录要处理,所以处理线程就再也没有执行了。
从ChangeLogScanProc代码分析,加上sql日志显示没有执行到update修改tb_change_log处理状态的命令.也就没有执行任务的处理线程队列的入队操作(ti->handler_.putq(mb)),不可能是队列阻塞造成的。
如此一来,扫描线程决无可能阻塞。
另外的可能是,ChangeLogScanProc产生了异常,导致线程函数没有机会再次运行(产生异常的线程处于什么状态?windows是如何对待产生异常的线程的?)。
但执行线程函数的ACE_THR_FUNC_RETURN exec_task_func(void *arg)有异常处理,而且还有bugreport守侯.
看来都漏掉了,有这种逻辑吗?
ACE_THR_FUNC_RETURN exec_task_func(void *arg) {
DeamonThreadArg *t_arg = ACE_reinterpret_cast(DeamonThreadArg*,arg);
DeamonTask *task = t_arg->task_;
ACE_THR_FUNC_RETURN status = 0;
HTX_TSS::instance()->SetDeamon(true);
do{
DWORD dwResult = WaitForSingleObject(task->signal_cond_var_,INFINITE);
// HTX_TSS::instance()->ClearThreadInfo();
if( task->state_ == 9 )
break;
if( dwResult == WAIT_OBJECT_0 || dwResult == WAIT_TIMEOUT ){
//task->state_ = 2;
HTX_LOGGER::instance()->log(LO_STDOUT|LO_FILE,SEVERITY_INFO,"DeamonTask[%s]:正在执行...\n",task->name_.c_str());
try {
status = (*task->func_)(task->arg_);
if (status&&HTX_DEAMON_MGR::instance()->error_handle_) { ///< 仅处理错误时才调用错误处理函数
(*HTX_DEAMON_MGR::instance()->error_handle_)(task,HTX_DEAMON_MGR::instance()->error_handle_arg_);
}
HTX_LOGGER::instance()->log(LO_STDOUT|LO_FILE,SEVERITY_INFO,"DeamonTask[%s]:执行完毕,返回码=%d.\n",task->name_.c_str(),status);
} catch(...) {
HTX_LOGGER::instance()->log(LO_STDOUT|LO_FILE,SEVERITY_ERROR,"DeamonTask[%s]异常.\n",task->name_.c_str());
continue;
}
//task->state_ = 3;
}
if (status==0) {
if( task->sche_strategy_ )
task->sche_strategy_->adjust();
if (task->done_cb_) {
(*task->done_cb_)(task->done_cb_arg_,task->sche_strategy_ ? task->sche_strategy_->get_last_task_time_tag() : 0); ///< @note 回调失败不会导致事务回滚,回调一般用于永久性记录最后任务时间.失败可能导致任务重复执行.(进程重新启动后)
}
}
if (task->get_active_flag()==0) ///< 测试线程是否活动
task->set_active_flag(1);
ResetEvent(task->signal_cond_var_); /// 设置为non-signal状态. (否则对于每日执行的任务,可能在上次执行过程中,task->signal_cond_var_在下一次定时到期时被设置为signal状态.导致执行多次)
}while(true);
delete t_arg;
return 0;
}
处理线程在当天日志中最后的记录为:(从日志和代码看应该是正常结束了)
[2014-10-13 20:11:10:814][线程25672][1][20][0][]HandleLogRecord正在处理:sheet_type=8,rule_id=8,app_pk=C_ID=C[Q11527-223-000111]...
[2014-10-13 20:11:10:814][线程25672][1][20][0][]正在处理数据抽取(规则:8,单据类型:100121050)...
[2014-10-13 20:11:10:830][线程25672][2][20][0][]数据抽取(规则:8,单据类型:100121050)开始处理...
[2014-10-13 20:11:10:846][线程25672][2][20][0][]数据抽取(规则:8,单据类型:100121050)时,明细记录数为1.主键:Q11527-223-000111,生成文件名:data\retail\autosend/se_imp_10012_100121050_1050_20141013_37308_1.xml
[2014-10-13 20:11:10:846][线程25672][2][20][0][]数据抽取(规则:8,单据类型:100121050)处理了1条记录,扫描记录数:1.
[2014-10-13 20:11:10:846][线程25672][1][20][0][]数据抽取(规则:8,单据类型:100121050)处理完毕,返回值:0
处理线程最早记录为:
[2014-10-13 06:29:26:878][线程25672][1][20][0][]HandleLogRecord正在处理:sheet_type=8,rule_id=8,app_pk=C_ID=C[1-228-004663]...
(3)失败重做线程15436始终在运行,有失败重做的活动。
[2014-10-13 20:27:43:565][线程15436][2][20][0][]DeamonTask[CRedoar::OnRedoProc]:正在执行...
2.处理
目前没有准确定位问题,以下的处理并不直接作用于此问题。此问题需要继续分析和跟踪。
(1)增加ChangeLogScanProc日志信息,在函数出入口,并输出扫描记录数,有效记录数,处理任务当前队列元素个数.为以后的问题诊断提供更多的信息.
已提交,未安排升级。
(2)检查失败重做队列表.如果存在反复执行始终无法成功的记录,则需要人工处理(如果是程序缺陷则需要修正完善)
线程15436是失败重做线程。
大量的重做项可能消耗了MySQL的资源.
需要分析下面2种应用的逻辑,分别是insert,update操作。
失败重做保存的是由于外部环境暂时失效,导致无法成功,但系统环境恢复后可以完成的任务。
检查失败重做队列表中的错误是否符合这个条件,表中不应该有永远不会成功的记录。
重做错误1:
[2014-10-13 23:58:49:793][线程15436][1][20][0][]正在处理机构30234的单据QR-02681-000194...
[2014-10-13 23:58:49:839][线程15436][5][20][0][]CDbAccessor2::Execute insert into tb_o_in(c_id,c_provider,c_status,c_at_should,c_a_should,c_tax_should,c_at_fact,c_a_fact,c_tax_fact,c_settle_region,c_mk_store_id,c_mk_userno,c_get_dt,c_at_pass_in,c_a_pass_in,c_tax_pass_in) values('QR-02681-000194','02681','尚未审核',10432.04,9083.66,1348.38,10432.04,9098.98,1333.06,'A0113','1','供应宝',NULL,'0.00','0.00','0.00')产生异常(Error
Code = 80040e14
Code meaning = IDispatch error #3092
Source = Microsoft OLE DB Provider for ODBC Drivers
Description =[Oracle][ODBC][Ora]ORA-00001: 违反唯一约束条件 (MIS_USER.TB_O_IN_PK)
([1]Number:0X80040E14 Description:[Oracle][ODBC][Ora]ORA-00001: 违反唯一约束条件 (MIS_USER.TB_O_IN_PK)
SQLState:23000 NativeError:1)).
[2014-10-13 23:58:49:855][线程15436][4][20][0][]LoadFromMsg返回值:-6.
[2014-10-13 23:58:49:902][线程15436][2][20][0][]DeamonTask[CRedoar::OnRedoProc]:执行完毕,返回码=0.
重做错误2:
[2014-10-13 02:14:16:956][线程15436][1][20][0][]正在处理机构10012的单据Q1116-147-000346...
[2014-10-13 02:14:17:206][线程15436][5][20][0][]CDbAccessor2::Execute update tb_o_i set c_booking_dt=to_date('2014-10-08 13:00:00','yyyy-MM-dd HH24:mi:ss') where c_id='Q1116-147-000346' and c_rec_status='尚未收货'产生异常(Error
Code = 80040e14
Code meaning = IDispatch error #3092
Source = Microsoft OLE DB Provider for ODBC Drivers
Description =[Oracle][ODBC][Ora]ORA-00001: 违反唯一约束条件 (DCSDBA.INTERFACE_PRE_HEADER_TIME_PK)
ORA-06512: 在 "MIS_USER.TR_RPWMS_PRE_ADVICE_TIME", line 17
ORA-04088: 触发器 'MIS_USER.TR_RPWMS_PRE_ADVICE_TIME' 执行过程中出错
([1]Number:0X80040E14 Description:[Oracle][ODBC][Ora]ORA-00001: 违反唯一约束条件 (DCSDBA.INTERFACE_PRE_HEADER_TIME_PK)
ORA-06512: 在 "MIS_USER.TR_RPWMS_PRE_ADVICE_TIME", line 17
ORA-04088: 触发器 'MIS_USER.TR_RPWMS_PRE_ADVICE_TIME' 执行过程中出错
SQLState:23000 NativeError:1)).
[2014-10-13 02:14:17:206][线程15436][4][20][0][]LoadFromMsg返回值:-1.