[OpenSIPS-Users] Delayed timer executions

Thu Sep 20 11:19:13 EDT 2018

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 ?

    On Thursday, 20 September 2018, 7:35:28 PM GMT+5:30, Dan Pascu <dan at ag-projects.com> wrote:  

 Here is a follow up on this problem. I started to use the system to do some testing. I only have 1 device registered that makes some calls. I started to notice similar type of messages, but with a slightly different pattern while testing it. They seem to happen more often when I end the call, but I cannot unequivocally tie the behavior to that because it doesn't happen always when I end a call, it just seems to be triggered more often during that time.

I see a string of warnings about timers that continue for about 30 seconds after which they stop, like below (I trimmed the output because it's just repeating every 90-100ms and the log would be too long, so I only pasted the start and the end of it):

Sep 20 10:28:34 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 100 ms ago (now 1208830 ms), delaying execution
Sep 20 10:28:34 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 200 ms ago (now 1208930 ms), delaying execution
Sep 20 10:28:34 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 300 ms ago (now 1209030 ms), delaying execution
Sep 20 10:28:34 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 400 ms ago (now 1209130 ms), delaying execution
Sep 20 10:28:34 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 500 ms ago (now 1209230 ms), delaying execution
Sep 20 10:28:34 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 600 ms ago (now 1209330 ms), delaying execution
Sep 20 10:28:34 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 700 ms ago (now 1209430 ms), delaying execution
Sep 20 10:28:34 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 800 ms ago (now 1209530 ms), delaying execution
Sep 20 10:28:34 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 900 ms ago (now 1209630 ms), delaying execution
Sep 20 10:28:34 node03 /usr/sbin/opensips[30302]: WARNING:core:timer_ticker: timer task <tm-timer> already scheduled 1000 ms ago (now 1209630 ms), delaying execution
Sep 20 10:28:34 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1000 ms ago (now 1209730 ms), delaying execution
Sep 20 10:28:35 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 1100 ms ago (now 1209830 ms), delaying execution

[...]

Sep 20 10:29:02 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 28760 ms ago (now 1237490 ms), delaying execution
Sep 20 10:29:02 node03 /usr/sbin/opensips[30302]: WARNING:core:timer_ticker: timer task <tm-timer> already scheduled 28860 ms ago (now 1237490 ms), delaying execution
Sep 20 10:29:02 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 28860 ms ago (now 1237590 ms), delaying execution
Sep 20 10:29:02 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 28960 ms ago (now 1237690 ms), delaying execution
Sep 20 10:29:03 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 29060 ms ago (now 1237790 ms), delaying execution
Sep 20 10:29:03 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 29160 ms ago (now 1237890 ms), delaying execution
Sep 20 10:29:03 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 29260 ms ago (now 1237990 ms), delaying execution
Sep 20 10:29:03 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 29360 ms ago (now 1238090 ms), delaying execution
Sep 20 10:29:03 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 29460 ms ago (now 1238190 ms), delaying execution
Sep 20 10:29:03 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 29560 ms ago (now 1238290 ms), delaying execution
Sep 20 10:29:03 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 29660 ms ago (now 1238390 ms), delaying execution
Sep 20 10:29:03 node03 /usr/sbin/opensips[30302]: WARNING:core:utimer_ticker: utimer task <tm-utimer> already scheduled 29750 ms ago (now 1238480 ms), delaying execution
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

On 17 Sep 2018, at 12:30, Dan Pascu wrote:

> 
> I quite often find these warnings in syslog. They happen on an opensips 2.4 installation that is completely idle (it does not process any messages at all, no registrations, no calls, no presence, nothing). Sometimes I see these warnings right after I start opensips, during the startup log, while the others happen randomly during the day.
> 
> The excerpt below is what I got from opensips running for a few days and being completely idle the whole time:
> 
> ./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
> ./opensips[21843]: WARNING:core:handle_timer_job: timer job <rls-notify> has a 40000 us delay in execution
> ./opensips[21850]: WARNING:core:handle_timer_job: timer job <nt-pinger> has a 40000 us delay in execution
> [...]

--
Dan

_______________________________________________
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/20180920/4b1f62ad/attachment-0001.html>