[SR-Users] rtimer execution period - round two

Alex Balashov abalashov at evaristesys.com
Tue Jul 24 04:26:38 CEST 2012 

Okay, ignore this bit.  I had a conflicting timer that I forgot about 
that was engaged at a 5 sec interval, thus polluting the results.  When 
I run my pure while() loop test routine and only it, it does not 
demonstrate this loop-breaking behaviour.

It still doesn't explain what is going on with my mqueue-consuming DB 
loop, though.  One easy explanation would be that mq_fetch() returns 0 
at some point, and the while() loop bottoms out, and doesn't run again 
for 'interval' (u)sec.  But then, why would I be showing the mqueue as 
growing and growing, not at 0 elements?

On 07/23/2012 10:02 PM, Alex Balashov wrote:

> 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.
>>>
>>
>>
>
>


-- 
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/

More information about the sr-users mailing list