[OpenSIPS-Users] UDP workers consume 100% CPU

[Vitalii Aleksandrov]

Hi,

I have a test opensips 2.4.6 (last week's checkout from 2.4 branch) and 
after short load testing it started to consume all CPU resources.

Here is what opensips floods to syslog:
Aug  3 13:25:01 l /opensips[4774]: WARNING:core:utimer_ticker: utimer 
task <tm-utimer> already scheduled for 114023190 ms (now 176231430 ms), 
it may overlap..
Aug  3 13:25:02 l /opensips[4774]: WARNING:core:utimer_ticker: utimer 
task <tm-utimer> already scheduled for 114023190 ms (now 176231530 ms), 
it may overlap..
Aug  3 13:25:02 l /opensips[4774]: WARNING:core:utimer_ticker: utimer 
task <tm-utimer> already scheduled for 114023190 ms (now 176231630 ms), 
it may overlap..
Aug  3 13:25:02 l /opensips[4774]: WARNING:core:utimer_ticker: utimer 
task <tm-utimer> already scheduled for 114023190 ms (now 176231730 ms), 
it may overlap..
Aug  3 13:25:02 l /opensips[4774]: WARNING:core:utimer_ticker: utimer 
task <tm-utimer> already scheduled for 114023190 ms (now 176231830 ms), 
it may overlap..
Aug  3 13:25:02 l /opensips[4774]: WARNING:core:utimer_ticker: utimer 
task <tm-utimer> already scheduled for 114023190 ms (now 176231930 ms), 
it may overlap..
Aug  3 13:25:02 l /opensips[4774]: WARNING:core:utimer_ticker: utimer 
task <tm-utimer> already scheduled for 114023190 ms (now 176232030 ms), 
it may overlap..
Aug  3 13:25:02 l /opensips[4774]: WARNING:core:timer_ticker: timer task 
<tm-timer> already scheduled for 114023090 ms (now 176232030 ms), it may 
overlap..

Where 4774 is: "Process::  ID=7 PID=4774 Type=timer"

Here is the TOP output for time consuming processes:
   PID USER         PR  NI    VIRT    RES      SHR    S  %CPU %MEM     
TIME+ COMMAND
  4801 opensips  20   0  721040  28496  24240 R  52.9  0.7 1817:08 opensips
  4802 opensips  20   0  721040  27724  23588 R  47.1  0.7 1813:06 opensips
  4806 opensips  20   0  721040  27640  23532 R  47.1  0.7 1814:41 opensips
  4833 opensips  20   0  721040  28848  24812 R  47.1  0.7 1815:16 opensips
  4803 opensips  20   0  721044  27928  23732 R  41.2  0.7 1817:09 opensips
  4804 opensips  20   0  721040  28188  23996 R  41.2  0.7 1816:05 opensips
  4799 opensips  20   0  721040  28272  24172 R  35.3  0.7 1813:29 opensips
  4800 opensips  20   0  721040  28340  24204 R  29.4  0.7 1816:52 opensips
  4805 opensips  20   0  723256  29620  25300 R  29.4  0.8 1819:28 opensips

And here is the "opensipsctl ps" for them:
Process::  ID=32 PID=4799 Type=SIP receiver udp:127.0.0.1:5070
Process::  ID=33 PID=4800 Type=SIP receiver udp:127.0.0.1:5070
Process::  ID=34 PID=4801 Type=SIP receiver udp:127.0.0.1:5070
Process::  ID=35 PID=4802 Type=SIP receiver udp:127.0.0.1:5070
Process::  ID=36 PID=4803 Type=SIP receiver udp:127.0.0.1:5070
Process::  ID=37 PID=4804 Type=SIP receiver udp:127.0.0.1:5070
Process::  ID=38 PID=4805 Type=SIP receiver udp:127.0.0.1:5070
Process::  ID=39 PID=4806 Type=SIP receiver udp:127.0.0.1:5070
Process::  ID=66 PID=4833 Type=TCP receiver

"strace" output for those burning processes just floods with:
11:07:04.042794 sched_yield()           = 0
11:07:04.042869 sched_yield()           = 0
11:07:04.042943 sched_yield()           = 0
11:07:04.043016 sched_yield()           = 0
11:07:04.043090 sched_yield()           = 0
11:07:04.043164 sched_yield()           = 0

Unfortunately this opensips is striped and gdb output is limited.
GDB bt of TCP receiver:
(gdb) bt
#0  0x00007f939211fe57 in sched_yield () at 
../sysdeps/unix/syscall-template.S:78
#1  0x00007f936fffc14d in ?? () from 
/usr/lib/x86_64-linux-gnu/opensips/modules/proto_tls.so
#2  0x00007f93791698d5 in send_pr_buffer () from 
/usr/lib/x86_64-linux-gnu/opensips/modules/tm.so
#3  0x00007f93791626b8 in relay_reply () from 
/usr/lib/x86_64-linux-gnu/opensips/modules/tm.so
#4  0x00007f937919fe2a in timer_routine () from 
/usr/lib/x86_64-linux-gnu/opensips/modules/tm.so
#5  0x000055e00034a58a in handle_timer_job ()
#6  0x000055e00041ae2a in tcp_worker_proc_loop ()
#7  0x000055e000427218 in tcp_start_processes ()
#8  0x000055e0002e6837 in main ()

GDB bt of UDP receiver:
#0  0x00007f939211fe57 in sched_yield () at 
../sysdeps/unix/syscall-template.S:78
#1  0x00007f936fffc14d in ?? () from 
/usr/lib/x86_64-linux-gnu/opensips/modules/proto_tls.so
#2  0x00007f93791698d5 in send_pr_buffer () from 
/usr/lib/x86_64-linux-gnu/opensips/modules/tm.so
#3  0x00007f93791626b8 in relay_reply () from 
/usr/lib/x86_64-linux-gnu/opensips/modules/tm.so
#4  0x00007f9379165015 in reply_received () from 
/usr/lib/x86_64-linux-gnu/opensips/modules/tm.so
#5  0x000055e000322fed in forward_reply ()
#6  0x000055e000309d1d in receive_msg ()
#7  0x000055e00042b4be in ?? ()
#8  0x000055e000413dd8 in udp_start_processes ()
#9  0x000055e0002e6724 in main ()

Those workers don't process any incoming SIP messages and just stay in 
this infinite loop.

Any input is very appreciated.