Re: [SR-Users] rtimer execution period - round two

Yeah, something's going on interrupting the execution of the route. I set the interval to 1:

modparam("rtimer", "timer", "name=test;interval=1;mode=1")

And then added this to the infinite for() loop in timer_proc.c:fork_basic_timer(), after the call to the timer_function:

LM_ERR("Bottomed out of timer loop\n"); if(tm_last > 0) { tm = time(NULL); LM_ERR("Execution gap: %d\n", tm - tm_last); }

tm_last = time(0); }

And here's what I got:

Jul 23 21:59:19 diminuendo-1 /usr/local/sbin/kamailio[2686]: INFO: Presented time gap: 1 Jul 23 21:59:20 diminuendo-1 /usr/local/sbin/kamailio[2686]: INFO: Presented time gap: 1 Jul 23 21:59:22 diminuendo-1 /usr/local/sbin/kamailio[2686]: INFO: Presented time gap: 1 Jul 23 21:59:22 diminuendo-1 /usr/local/sbin/kamailio[2687]: ERROR: rtimer [rtimer_mod.c:194]: Bottomed out of top route execution Jul 23 21:59:22 diminuendo-1 /usr/local/sbin/kamailio[2687]: ERROR: <core> [timer_proc.c:94]: Bottomed out of timer loop Jul 23 21:59:23 diminuendo-1 /usr/local/sbin/kamailio[2686]: INFO: Presented time gap: 1 Jul 23 21:59:25 diminuendo-1 /usr/local/sbin/kamailio[2686]: INFO: Presented time gap: 1 Jul 23 21:59:26 diminuendo-1 /usr/local/sbin/kamailio[2686]: INFO: Presented time gap: 1 Jul 23 21:59:27 diminuendo-1 /usr/local/sbin/kamailio[2687]: ERROR: rtimer [rtimer_mod.c:194]: Bottomed out of top route execution Jul 23 21:59:27 diminuendo-1 /usr/local/sbin/kamailio[2687]: ERROR: <core> [timer_proc.c:94]: Bottomed out of timer loop Jul 23 21:59:27 diminuendo-1 /usr/local/sbin/kamailio[2687]: ERROR: <core> [timer_proc.c:99]: Execution gap: 5 Jul 23 21:59:32 diminuendo-1 /usr/local/sbin/kamailio[2687]: ERROR: rtimer [rtimer_mod.c:194]: Bottomed out of top route execution Jul 23 21:59:32 diminuendo-1 /usr/local/sbin/kamailio[2687]: ERROR: <core> [timer_proc.c:94]: Bottomed out of timer loop Jul 23 21:59:32 diminuendo-1 /usr/local/sbin/kamailio[2687]: ERROR: <core> [timer_proc.c:99]: Execution gap: 5

There is definitely something dependably interrupting the execution once in a while (every 5 sec).

On 07/23/2012 09:23 PM, Alex Balashov wrote:

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.