23 Jul
2012
23 Jul
'12
9:23 p.m.
I think some sort of execution time governor in the actions
infrastructure is probably the right angle here.
I added a log statement to modules_k/rtimer/rtimer_mod.c:stm_timer_exec():
for(rt=it->rt; rt; rt=rt->next)
{
fmsg = faked_msg_next();
if (exec_pre_script_cb(fmsg, REQUEST_CB_TYPE)==0 )
continue; /* drop the request */
set_route_type(REQUEST_ROUTE);
run_top_route(main_rt.rlist[rt->route], fmsg, 0);
LM_ERR("Fell out of route execution: %u\n", time(NULL));
exec_post_script_cb(fmsg, REQUEST_CB_TYPE);
}
And here's what I saw, with the previous test task (quoted in the
message above which I am posting):
Jul 23 21:20:15 diminuendo-1 /usr/local/sbin/kamailio[26255]: ERROR:
rtimer [rtimer_mod.c:192]: Fell out of route execution: 1343092815
Jul 23 21:20:19 diminuendo-1 /usr/local/sbin/kamailio[26254]: INFO:
Presented time gap: 1
Jul 23 21:20:20 diminuendo-1 /usr/local/sbin/kamailio[26255]: ERROR:
rtimer [rtimer_mod.c:192]: Fell out of route execution: 1343092820
Jul 23 21:20:22 diminuendo-1 /usr/local/sbin/kamailio[26254]: INFO:
Presented time gap: 1
Jul 23 21:20:24 diminuendo-1 /usr/local/sbin/kamailio[26254]: INFO:
Presented time gap: 1
Jul 23 21:20:25 diminuendo-1 /usr/local/sbin/kamailio[26254]: INFO:
Presented time gap: 1
Jul 23 21:20:25 diminuendo-1 /usr/local/sbin/kamailio[26255]: ERROR:
rtimer [rtimer_mod.c:192]: Fell out of route execution: 1343092825
Jul 23 21:20:28 diminuendo-1 /usr/local/sbin/kamailio[26254]: INFO:
Presented time gap: 1
Jul 23 21:20:29 diminuendo-1 /usr/local/sbin/kamailio[26254]: INFO:
Presented time gap: 1
Jul 23 21:20:30 diminuendo-1 /usr/local/sbin/kamailio[26255]: ERROR:
rtimer [rtimer_mod.c:192]: Fell out of route execution: 1343092830
Jul 23 21:20:31 diminuendo-1 /usr/local/sbin/kamailio[26254]: INFO:
Presented time gap: 1
Jul 23 21:20:35 diminuendo-1 /usr/local/sbin/kamailio[26254]: INFO:
Presented time gap: 1
Jul 23 21:20:35 diminuendo-1 /usr/local/sbin/kamailio[26255]: ERROR:
rtimer [rtimer_mod.c:192]: Fell out of route execution: 1343092835
Jul 23 21:20:36 diminuendo-1 /usr/local/sbin/kamailio[26254]: INFO:
Presented time gap: 1
Jul 23 21:20:37 diminuendo-1 /usr/local/sbin/kamailio[26254]: INFO:
Presented time gap: 1
Jul 23 21:20:38 diminuendo-1 /usr/local/sbin/kamailio[26254]: INFO:
Presented time gap: 1
Shouldn't that while() loop in the script run to infinity?
(max_while_loops is set to 0)
On 07/23/2012 09:12 PM, Alex Balashov wrote:
I did an experiment to try to simplify the problem,
and rule out mqueue
concurrency/locking issues:
modparam("pv", "shvset", "lasttm=i:-1")
modparam("rtimer", "timer",
"name=test;interval=1;mode=1")
modparam("rtimer", "exec",
"timer=test;route=TEST_ROUTE")
route[TEST_ROUTE] {
while(1) {
if($shv(lasttm) < 0)
$shv(lasttm) = $TV(sn);
else {
$var(gap) = $TV(sn) - $shv(lasttm);
if($var(gap) >= 1) {
xlog("L_INFO", "Presented time gap:
$var(gap)\n");
}
}
$shv(lasttm) = $TV(sn);
}
}
And here's what I saw in the log:
Jul 23 21:10:07 diminuendo-1 /usr/local/sbin/kamailio[26073]: INFO:
Presented time gap: 1
Jul 23 21:10:12 diminuendo-1 /usr/local/sbin/kamailio[26073]: INFO:
Presented time gap: 1
Jul 23 21:10:13 diminuendo-1 /usr/local/sbin/kamailio[26073]: INFO:
Presented time gap: 1
Jul 23 21:10:16 diminuendo-1 /usr/local/sbin/kamailio[26073]: INFO:
Presented time gap: 1
Jul 23 21:10:18 diminuendo-1 /usr/local/sbin/kamailio[26073]: INFO:
Presented time gap: 1
Jul 23 21:10:21 diminuendo-1 /usr/local/sbin/kamailio[26073]: INFO:
Presented time gap: 1
Jul 23 21:10:23 diminuendo-1 /usr/local/sbin/kamailio[26073]: INFO:
Presented time gap: 1
Jul 23 21:10:29 diminuendo-1 /usr/local/sbin/kamailio[26073]: INFO:
Presented time gap: 1
Jul 23 21:10:30 diminuendo-1 /usr/local/sbin/kamailio[26073]: INFO:
Presented time gap: 1
Jul 23 21:10:34 diminuendo-1 /usr/local/sbin/kamailio[26073]: INFO:
Presented time gap: 1
Jul 23 21:10:36 diminuendo-1 /usr/local/sbin/kamailio[26073]: INFO:
Presented time gap: 1
Jul 23 21:10:38 diminuendo-1 /usr/local/sbin/kamailio[26073]: INFO:
Presented time gap: 1
Jul 23 21:10:39 diminuendo-1 /usr/local/sbin/kamailio[26073]: INFO:
Presented time gap: 1
Jul 23 21:10:40 diminuendo-1 /usr/local/sbin/kamailio[26073]: INFO:
Presented time gap: 1
Jul 23 21:10:43 diminuendo-1 /usr/local/sbin/kamailio[26073]: INFO:
Presented time gap: 1
When I repeated the experiment with interval=3:
Jul 23 21:11:51 diminuendo-1 /usr/local/sbin/kamailio[26132]: INFO:
Presented time gap: 1
Jul 23 21:11:52 diminuendo-1 /usr/local/sbin/kamailio[26132]: INFO:
Presented time gap: 1
Jul 23 21:11:54 diminuendo-1 /usr/local/sbin/kamailio[26132]: INFO:
Presented time gap: 1
Jul 23 21:11:55 diminuendo-1 /usr/local/sbin/kamailio[26132]: INFO:
Presented time gap: 1
Jul 23 21:11:56 diminuendo-1 /usr/local/sbin/kamailio[26132]: INFO:
Presented time gap: 1
Jul 23 21:11:59 diminuendo-1 /usr/local/sbin/kamailio[26132]: INFO:
Presented time gap: 1
Jul 23 21:12:03 diminuendo-1 /usr/local/sbin/kamailio[26132]: INFO:
Presented time gap: 1
Jul 23 21:12:04 diminuendo-1 /usr/local/sbin/kamailio[26132]: INFO:
Presented time gap: 1
So, something is definitely interrupting the possibility of continuous
execution of these rtimer tasks.
--
Alex Balashov - Principal
Evariste Systems LLC
235 E Ponce de Leon Ave
Suite 106
Decatur, GA 30030
Tel: +1-678-954-0670
Fax: +1-404-961-1892
Web: http://www.evaristesys.com/, http://www.alexbalashov.com/