[OpenSIPS-Users] Delayed timer executions

[Bogdan-Andrei Iancu]

Dan,

For the delay warnings, that's what the code does - it checks time 
difference (internal ticker) between writing and reading from a pipe. If 
you there is no load (to prevent the workers to read from the pipe), the 
only delay may come from the actual pipe communication. Why the delay, 
not sure for me too.

On the second issue (already scheduled), the warning reports an almost 
that the timer job was triggered almost 30 seconds ago without 
completing (note that the timestamp between the brackets is the absolute 
time from start, not a diff -> the 21 minutes are the uptime, not the 
delay).

When you get such warnings, try to run an "opensipsctl trap" , maybe we 
can see what the timer job is doing - I guess it is very slow (in 
whatever doing).

Regards,

Bogdan-Andrei Iancu

OpenSIPS Founder and Developer
   http://www.opensips-solutions.com
OpenSIPS Bootcamp 2018
   http://opensips.org/training/OpenSIPS_Bootcamp_2018/

On 09/20/2018 08:16 PM, Dan Pascu wrote:
> On 20 Sep 2018, at 19:06, Bogdan-Andrei Iancu wrote:
>
>> Hi Dan,
>>
>> Copying from my previous reply to Pasan:
>>
>>
>> "If there is no load (worker processes are idle, no busy with anything else), the reported delay may be generated only by the interprocess communication (passing the job from the triggering process to the executing process via internal pipes).
>>
>> What are the values you typically observe ? maybe the warning is jst about a slow context switching on your server (btw, how many cores ?)."
> While I would agree with you for these messages:
>
> ./opensips[21850]: WARNING:core:handle_timer_job: timer job <dlg-options-pinger> has a 40000 us delay in execution
> ./opensips[21850]: WARNING:core:handle_timer_job: timer job <dlg-reinvite-pinger> has a 50000 us delay in execution
>
> that indicate a 40-50ms delay, I do not think that you can blame context switching for these messages:
>
> Sep 20 10:29:03 node03 /usr/sbin/opensips[30302]: WARNING:core:timer_ticker: timer task <tm-timer> already scheduled 29850 ms ago (now 1238480 ms), delaying execution
> Sep 20 10:29:03 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 29850 ms ago (now 1238580 ms), delaying execution
>
> If I read them correctly they say that the timer was already scheduled 30 seconds ago and the timer already has a lifetime of 1238 seconds - almost 21minutes!!! - and still hasn't fired yet.
>
> Plus the system I use is a 4 core real machine, so how bad can the context switching be that I see my log flooded with these messages (the later type of messages were logged every 100ms for 30 seconds - which makes them like 300 log messages whenever this happens)?
>
> Re-read my second message on the matter, because those do not look like context switching.
>
>> Regards,
>>
>> Bogdan-Andrei Iancu
>>
>> OpenSIPS Founder and Developer
>>   http://www.opensips-solutions.com
>> OpenSIPS Bootcamp 2018
>>   http://opensips.org/training/OpenSIPS_Bootcamp_2018/
>>
>> On 09/20/2018 06:55 PM, Dan Pascu wrote:
>>> On 20 Sep 2018, at 18:19, Pasan Meemaduma via Users wrote:
>>>
>>>> Hi Dan,
>>>>
>>>> I'm experiencing same on 2.3.5 as per my initial email. still couldn't find out the exact reason. btw are you using a virtualise environment ?
>>> No
>>>
>>> --
>>> Dan
>>>
>>>
>>>
>>>
>>>
>>> _______________________________________________
>>> Users mailing list
>>> Users at lists.opensips.org
>>> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>
> --
> Dan
>
>
>
>