[SR-Users] rtimer execution period - round two

[Daniel-Constantin Mierla]

Hello,

On 7/24/12 4:46 AM, Alex Balashov wrote:
> On 07/23/2012 08:38 PM, Alex Balashov wrote:
>
>>      route[ACCT_WRITER] {
>>         while(mq_fetch("acct_write")) {
>>            # Some stuff to write $mqv(...) values to PostgreSQL.
>>
>>            ...
>>
>>            sql_query("ca", "SELECT * FROM acct_event_proc(...)");
>>            ...
>>
>>            mq_pv_free("acct_write");
>>         }
>>      }
>
> I added the mq_size() function in script:
>
> http://git.sip-router.org/cgi-bin/gitweb.cgi?p=sip-router;a=commit;h=f492b41bd12904e3132260562073e79d76a003a5 
>
>
> Then, added this to the bottom of this route:
>
>         $var(sz) = mq_size("acct_write");
>
>         if($var(sz) > 0)
>                 xlog("L_INFO", "Exiting request route with mq size: 
> $var(sz)\n");
I assume the xlog message above is starting ' Executing ...' as showed 
in next logs.

Have you tried it with the log message in the sources to see if it goes 
after the C code line:

                 run_top_route(main_rt.rlist[rt->route], fmsg, 0);

?

The way mqueue is consuming items from queue does not ensure queue 
locking until all items are consumed. So the first item there is removed 
from queue and cloned in private memory where is accessible via PV, then 
the queue is unlocked so others can consume or add to it.

Not being in office for few days, I cannot run tests myself ... do you 
have heavy writers? Can you add few more timer processes to consume from 
queue and see what happens?

Cheers,
Daniel

>
> And, I'm seeing this in the log, running at a 1-second interval:
>
> Jul 24 22:41:59 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 229
> Jul 24 22:42:00 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 82
> Jul 24 22:42:05 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 328
> Jul 24 22:42:11 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 689
> Jul 24 22:42:15 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 946
> Jul 24 22:42:22 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1586
> Jul 24 22:42:27 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1783
> Jul 24 22:42:32 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1964
> Jul 24 22:42:37 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2346
> Jul 24 22:42:39 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2323
> Jul 24 22:42:41 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2210
> Jul 24 22:42:45 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2224
> Jul 24 22:42:46 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2056
> Jul 24 22:42:47 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1904
> Jul 24 22:42:48 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1798
> Jul 24 22:42:49 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1619
> Jul 24 22:42:53 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1651
> Jul 24 22:42:54 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1467
> Jul 24 22:42:55 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1378
> Jul 24 22:42:56 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1206
> Jul 24 22:42:59 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1220
> Jul 24 22:43:04 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1542
> Jul 24 22:43:08 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1733
> Jul 24 22:43:13 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1846
> Jul 24 22:43:21 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2437
> Jul 24 22:43:26 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2751
> Jul 24 22:43:29 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2734
> Jul 24 22:43:33 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2778
> Jul 24 22:43:35 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2742
> Jul 24 22:43:37 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2582
> Jul 24 22:43:42 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2828
> Jul 24 22:43:44 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2663
> Jul 24 22:43:45 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2490
> Jul 24 22:43:46 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2339
> Jul 24 22:43:47 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2153
> Jul 24 22:43:49 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2022
> Jul 24 22:43:53 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2182
> Jul 24 22:43:54 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2002
> Jul 24 22:43:55 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1813
> Jul 24 22:43:57 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1638
> Jul 24 22:43:58 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1439
> Jul 24 22:44:02 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1452
> Jul 24 22:44:06 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1640
> Jul 24 22:44:11 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 1836
> Jul 24 22:44:17 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2120
> Jul 24 22:44:22 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2156
> Jul 24 22:44:27 diminuendo-1 /usr/local/sbin/kamailio[31118]: INFO: 
> Executing request route with mq size: 2495
>
> So, perhaps my issue comes down to the while() loop breaking before 
> the queue is truly empty.  That is, unless those thousands of records 
> are somehow showing up between the while() condition evaluation and my 
> log statement, which seems quite unlikely.  Any way to fix that?
>

-- 
Daniel-Constantin Mierla - http://www.asipto.com
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Kamailio Advanced Training, Seattle, USA, Sep 23-26, 2012 - http://asipto.com/u/katu
Kamailio Practical Workshop, Netherlands, Sep 10-12, 2012 - http://asipto.com/u/kpw