[OpenSIPS-Users] Is there new information about "WARNING ...tm-utimer...delay in execution" nowadays ?

[Bogdan-Andrei Iancu]

Hi Rodrigo,

The issue you are reporting it is not the real problem, but a side 
effect of it. As you noticed, when opensips is under heavy load (CPU?), 
the internal timer system starts to generate warnings you see.

Now, the questions is: why is your opensips using 100% or why is it 
blocked (no processes available). Do you have any input on this ?

Regards,

Bogdan-Andrei Iancu
   OpenSIPS Founder and Developer
   http://www.opensips-solutions.com

OpenSIPS Summit May 2017 Amsterdam
   http://www.opensips.org/events/Summit-2017Amsterdam.html

On 03/20/2017 09:10 PM, Rodrigo Pimenta Carvalho wrote:
>
>
> Hi.
>
>
> I have seen again that behavior from OpenSIPS that generates lots of 
> warnings, like below:
>
>
>
> Jan 01 06:19:08 colibri-imx6 opensips[1785]: Jan  1 06:19:08 [1792] 
> WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 
> for 21873780 ms (now 21873970 ms), it may overlap..
> Jan 01 06:19:08 colibri-imx6 opensips[1785]: Jan  1 06:19:08 [1792] 
> WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 
> for 21873990 ms (now 21873990 ms), it may overlap..
> Jan 01 06:19:08 colibri-imx6 opensips[1785]: Jan  1 06:19:08 [1793] 
> WARNING:core:handle_timer_job: utimer job <tm-utimer> has a 190000 us 
> delay in execution
> Jan 01 06:19:26 colibri-imx6 opensips[1785]: Jan  1 06:19:26 [1792] 
> WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 
> for 0 ms (now 21891940 ms), it may overlap..
> Jan 01 06:19:43 colibri-imx6 opensips[1785]: Jan  1 06:19:43 [1792] 
> WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 
> for 21908780 ms (now 21909000 ms), it may overlap..
> Jan 01 06:19:43 colibri-imx6 opensips[1785]: Jan  1 06:19:43 [1792] 
> WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 
> for 21909010 ms (now 21909010 ms), it may overlap..
> Jan 01 06:19:43 colibri-imx6 opensips[1785]: Jan  1 06:19:43 [1794] 
> WARNING:core:handle_timer_job: utimer job <tm-utimer> has a 220000 us 
> delay in execution
> Jan 01 06:19:43 colibri-imx6 opensips[1785]: Jan  1 06:19:43 [1797] 
> WARNING:core:handle_timer_job: timer job <tm-timer> has a 220000 us 
> delay in execution
> Jan 01 06:19:43 colibri-imx6 opensips[1785]: Jan  1 06:19:43 [1795] 
> WARNING:core:handle_timer_job: timer job <dlg-timer> has a 220000 us 
> delay in execution
> Jan 01 06:19:43 colibri-imx6 opensips[1785]: Jan  1 06:19:43 [1793] 
> WARNING:core:handle_timer_job: timer job <blcore-expire> has a 230000 
> us delay in execution
> Jan 01 06:19:49 colibri-imx6 opensips[1785]: Jan  1 06:19:49 [1798] 
> WARNING:core:handle_timer_job: utimer job <tm-utimer> has a 370000 us 
> delay in execution
> Jan 01 06:19:49 colibri-imx6 opensips[1785]: Jan  1 06:19:49 [1792] 
> WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 
> for 21914930 ms (now 21915300 ms), it may overlap..
> Jan 01 06:19:49 colibri-imx6 opensips[1785]: Jan  1 06:19:49 [1792] 
> WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 
> for 21915320 ms (now 21915320 ms), it may overlap..
> Jan 01 06:19:49 colibri-imx6 opensips[1785]: Jan  1 06:19:49 [1794] 
> WARNING:core:handle_timer_job: utimer job <tm-utimer> has a 30000 us 
> delay in execution
> Jan 01 06:19:49 colibri-imx6 opensips[1785]: Jan  1 06:19:49 [1795] 
> WARNING:core:handle_timer_job: utimer job <tm-utimer> has a 30000 us 
> delay in execution
>
> When it happens, I can see that OpenSIPS is using the CPU almost 100% 
> of the time. And such behavior prevents others softwares in my system 
> to work without problems. I see 6 process with 'OpenSIPS name and each 
> one using 11% of CPU, for example. Now, the unique solution is to 
> reboot the system. Otherwise, the system remains instable and OpenSIPS 
> continues using the CPU much more than usual.
>
> Is there some new information about such issue that I should to know 
> nowadays?
> Is my hardware under minimals requirements to run OpenSIPS?
> Is my script opensips.cfg wrong?
>
> My system has the following characteristics:
>
>     CPU clock = 996000
>     CPU model name    = ARMv7 Processor rev 10 (v7l)
>      Hardware    =  Freescale i.MX6 Quad/DualLite (Device Tree)
>
>                            total       used free     shared    
> buffers     cached
>     Mem:        251140     157208      93932 0        196      26304
>
>
>
> In my script opensips.cfg I have:
> -----------------------------------------------
> tcp_children=4
> tcp_keepalive = 1
> children=4
> #fork=no
> auto_aliases=no
>
> #### Transaction Module
> loadmodule "tm.so"
> modparam("tm", "fr_timeout", 90)
> modparam("tm", "fr_inv_timeout", 120)
> modparam("tm", "T1_timer", 3000)
> modparam("tm", "restart_fr_on_each_reply", 0)
> modparam("tm", "onreply_avp_mode", 1)
>
> Any hint will be very helpful!
>
> Best regards.
>
>
>
>
> RODRIGO PIMENTA CARVALHO
> Inatel Competence Center
> Software
> Ph: +55 35 3471 9200 RAMAL 979
>
>
> _______________________________________________
> Users mailing list
> Users at lists.opensips.org
> http://lists.opensips.org/cgi-bin/mailman/listinfo/users

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20170322/4747a595/attachment.html>