Hello,
So I wrote a script that watches opensips log for log_expiry warning and
collects per-process
cpu utilization (using 'top' command) when such entry appears in the log.
Here's what it found:
LOG:
Dec 14 19:50:41 csp-p1n1 csp1[19109]: WARNING:core:log_expiry: threshold
exceeded : msg processing took too long - 148363 us.Source : REGISTER
sip:csp1.example.com:5060 SIP/2.0
Dec 14 19:50:41 csp-p1n1 csp1[19109]: WARNING:core:log_expiry: #1 is a module
action : subst - 147916us - line 1308
Dec 14 19:50:41 csp-p1n1 csp1[19109]: WARNING:core:log_expiry: #2 is a module
action : t_replicate - 78us - line 1310
Dec 14 19:50:41 csp-p1n1 csp1[19109]: WARNING:core:log_expiry: #3 is a module
action : save - 61us - line 1291
Dec 14 19:50:41 csp-p1n1 csp1[19109]: WARNING:core:log_expiry: #4 is a module
action : avp_subst - 34us - line 907
Dec 14 19:50:41 csp-p1n1 csp1[19109]: WARNING:core:log_expiry: #5 is a module
action : pv_www_authorize - 15us - line 1254
TOP:
top - 19:50:41 up 350 days, 2:31, 0 users, load average: 0.53, 0.33, 0.27
Tasks: 196 total, 3 running, 193 sleeping, 0 stopped, 0 zombie
Cpu(s): 0.5%us, 0.5%sy, 0.0%ni, 98.7%id, 0.3%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 4005248k total, 3776444k used, 228804k free, 286420k buffers
Swap: 2097144k total, 40960k used, 2056184k free, 1850068k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
19109 opensips 20 0 696m 19m 16m S 30 0.5 26:28.04 opensips
19104 opensips 20 0 696m 19m 16m S 2 0.5 26:33.08 opensips
19105 opensips 20 0 696m 19m 16m S 2 0.5 26:28.10 opensips
1 root 20 0 4356 572 492 S 0 0.0 13366:15 init
2 root 20 0 0 0 0 S 0 0.0 0:06.93 kthreadd
3 root 20 0 0 0 0 S 0 0.0 24:34.15 ksoftirqd/0
5 root 0 -20 0 0 0 S 0 0.0 0:00.00 kworker/0:0H
7 root RT 0 0 0 0 S 0 0.0 1:56.92 migration/0
opensips itself utilized 30% of cpu time.
here's another example:
LOG:
Dec 14 21:07:29 csp-p1n1 csp1[19110]: WARNING:core:log_expiry: threshold
exceeded : msg processing took too long - 148509 us.Source : NOTIFY
sip:[email protected]:5061 SIP/2.0
Dec 14 21:07:29 csp-p1n1 csp1[19110]: WARNING:core:log_expiry: #1 is a module
action : avp_subst - 63us - line 907
Dec 14 21:07:29 csp-p1n1 csp1[19110]: WARNING:core:log_expiry: #2 is a module
action : t_relay - 57us - line 1116
Dec 14 21:07:29 csp-p1n1 csp1[19110]: WARNING:core:log_expiry: #3 is a core
action : 69 - 15us - line 941
Dec 14 21:07:29 csp-p1n1 csp1[19110]: WARNING:core:log_expiry: #4 is a module
action : sipmsg_validate - 14us - line 1002
Dec 14 21:07:29 csp-p1n1 csp1[19110]: WARNING:core:log_expiry: #5 is a module
action : lookup - 13us - line 1631
TOP:
top - 21:07:29 up 350 days, 3:48, 0 users, load average: 0.15, 0.29, 0.31
Tasks: 196 total, 1 running, 195 sleeping, 0 stopped, 0 zombie
Cpu(s): 0.5%us, 0.5%sy, 0.0%ni, 98.7%id, 0.3%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 4005248k total, 3773700k used, 231548k free, 285912k buffers
Swap: 2097144k total, 40960k used, 2056184k free, 1854896k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
19110 opensips 20 0 696m 19m 16m S 30 0.5 26:31.94 opensips
9 root 20 0 0 0 0 S 2 0.0 184:25.29 rcu_sched
19104 opensips 20 0 696m 19m 16m S 2 0.5 26:39.33 opensips
19112 opensips 20 0 696m 19m 16m S 2 0.5 26:27.47 opensips
19115 opensips 20 0 696m 19m 16m S 2 0.5 26:33.44 opensips
19118 opensips 20 0 696m 19m 16m S 2 0.5 26:33.73 opensips
25899 root 19 -1 193m 24m 11m S 2 0.6 6487:27 corosync
1 root 20 0 4356 572 492 S 0 0.0 13366:15 init
2 root 20 0 0 0 0 S 0 0.0 0:06.93 kthreadd
3 root 20 0 0 0 0 S 0 0.0 24:35.13 ksoftirqd/0
5 root 0 -20 0 0 0 S 0 0.0 0:00.00 kworker/0:0H
again opensips itself utilized 30% of cpu time. in addition log_expiry message
doesn't show a single action that would take long, just the whole message
processing takes ~150ms.
it looks like opensips for no obvious reasons randomly spikes its cpu
utilization. it's not periodic, doesn't correspond to any periodic process in
the system and looks completely random.
i checked with MI 'ps' command and those cpu-spiking processes are all "SIP
receiver" processes.
I'm at loss. What could be causing opensips process to spike its cpu usage like
that?
I'd appreciate any ideas.
Thanks,
Michael
On Wednesday, December 02, 2015 07:19:06 PM Liviu Chircu wrote:
> Hi Michael,
>
> The subst() warning is very interesting, since it's not doing I/O at all
> (bonus: it's not even allocating shared memory!).
>
> So first thing that comes to mind is some excessive CPU usage happening
> on your machine. Some cron job or daemon which may be CPU starving the
> OpenSIPS workers from time to time?
>
> Best regards,
>
> Liviu Chircu
> OpenSIPS Developer
> http://www.opensips-solutions.com
> _______________________________________________
Users mailing list
[email protected]
http://lists.opensips.org/cgi-bin/mailman/listinfo/users
