Hi Richard,
Those warning means that a certain timer is really busy, overlapping
between executions - here is about the tm-utimer, responsible for
performing the stateful retransmissions (upon missing replies). Such a
timer may get slow due to TCP stuff, like trying to retransmit to
disconnected connections.
Best regards,
Bogdan-Andrei Iancu
OpenSIPS Founder and Developer
https://www.opensips-solutions.com
https://www.siphub.com
On 26.06.2025 01:24, Richard Revels via Users wrote:
Ah, Thank You. Yes, I have come to the same conclusion that those
messages are after the problem rather than before. I didn't take
enough time to really dig into the logs before send that message I reckon.
On Wed, Jun 25, 2025 at 1:20 PM Gregory Massel via Users
<users@lists.opensips.org> wrote:
I get these on my most lightly loaded system, yet none at all on
my most heavily loaded system...
Although the error is generic enough that, on its own, it doesn't
really help to determine what the problem is, on my system the
tm-utimer messages are often accompanied by TLS errors such as:
ERROR:tls_wolfssl:_wolfssl_tls_conn_shutdown: no ssl data
ERROR:tm:msg_send: send() to x.x.x.x:5061 for proto tls/3 failed
(Note: While I'm currently using WolfSSL, I previously used
OpenSSL and experienced similar issues.)
That's not to say that you're getting the error for the same
reason as me; just to point out that there should be related
errors before or after the tm-utimer warnings. It may be tricky to
find them on a system with your sorts of volumes as, in my case,
the TLS errors are typically just over 2 minutes AFTER the
tm-utimer warnings. On a busy system, a lot of unrelated log
entries are likely to generate in between.
The low-load system with these issue has outbound TLS. The
high-load system without these issues does no outbound TLS; the
only TLS it handles are inbound WSS connections.
With regard to your question about threads, take a look at:
https://www.opensips.org/Documentation/Script-CoreParameters-3-4#tcp_workers
https://www.opensips.org/Documentation/Script-CoreParameters-3-4#udp_workers
--Greg
On 2025-06-24 18:52, Richard Revels via Users wrote:
Greetings,
I have started having issues with some proxies running opensips
3.2.19 and some others running 3.4.12
With approximately 230 cps and 7300 dialogs the proxy starts
emitting log messages like
Jun 24 15:42:18 sip-proxy.local
/usr/local/opensips/sbin/opensips[190328]:
WARNING:core:utimer_ticker: utimer task <tm-utimer> already
scheduled 150 ms ago (now 3671145080 ms), delaying execution
Jun 24 15:42:18 sip-proxy.local
/usr/local/opensips/sbin/opensips[190328]:
WARNING:core:utimer_ticker: utimer task <tm-utimer> already
scheduled 200 ms ago (now 3671145130 ms), delaying execution
Jun 24 15:42:18 sip-proxy.local
/usr/local/opensips/sbin/opensips[190328]:
WARNING:core:utimer_ticker: utimer task <tm-utimer> already
scheduled 300 ms ago (now 3671145230 ms), delaying execution
Jun 24 15:42:18 sip-proxy.local
/usr/local/opensips/sbin/opensips[190328]:
WARNING:core:utimer_ticker: utimer task <tm-utimer> already
scheduled 400 ms ago (now 3671145330 ms), delaying execution
Jun 24 15:42:18 sip-proxy.local
/usr/local/opensips/sbin/opensips[190328]:
WARNING:core:utimer_ticker: utimer task <tm-utimer> already
scheduled 500 ms ago (now 3671145430 ms), delaying execution
Jun 24 15:42:19 sip-proxy.local
/usr/local/opensips/sbin/opensips[190328]:
WARNING:core:utimer_ticker: utimer task <tm-utimer> already
scheduled 600 ms ago (now 3671145530 ms), delaying execution
Jun 24 15:42:19 sip-proxy.local
/usr/local/opensips/sbin/opensips[190328]:
WARNING:core:utimer_ticker: utimer task <tm-utimer> already
scheduled 700 ms ago (now 3671145630 ms), delaying execution
Jun 24 15:42:19 sip-proxy.local
/usr/local/opensips/sbin/opensips[190328]:
WARNING:core:utimer_ticker: utimer task <tm-utimer> already
scheduled 800 ms ago (now 3671145730 ms), delaying execution
Jun 24 15:42:19 sip-proxy.local
/usr/local/opensips/sbin/opensips[190328]:
WARNING:core:utimer_ticker: utimer task <tm-utimer> already
scheduled 900 ms ago (now 3671145830 ms), delaying execution
Jun 24 15:42:19 sip-proxy.local
/usr/local/opensips/sbin/opensips[190328]:
WARNING:core:timer_ticker: timer task <tm-timer> already
scheduled 1000 ms ago (now 3671145830 ms), delaying execution
The cpu usage on the threads goes from 3% - 11% depending on
thread to 30% across the board.
I have been running these versions of opensips for some time now
(months for 3.4 and years for 3.2) and do see occasional latency
in db or rest connection responses but only recently have started
having this issue.
So,
How are SIP calls distributed across the processing threads? I
was thinking it would be round robin w/ attention given to busy
or not. but it seems like the lower pid threads do a lot more
work on these proxies
What are possible causes of the timers having trouble completing
tasks? is it cpu use, waiting on some other task to finish,
combination or more?
Is there tuning that can be done to have more timer handling
threads? i tried this with modparam("tm", "timer_partitions")
which seemed to make the problem worse
Thank you in advance for any guidance you can give me on
troubleshooting this issue.
Richard Revels
_______________________________________________
Users mailing list
Users@lists.opensips.org
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
_______________________________________________
Users mailing list
Users@lists.opensips.org
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
_______________________________________________
Users mailing list
Users@lists.opensips.org
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
_______________________________________________
Users mailing list
Users@lists.opensips.org
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
