[OpenSIPS-Users] opensips taking 100% cpu

Tue Jul 21 20:16:58 CEST 2015

Hi Bogdan,

Performance testing is really getting hit because of this issue. I will appreciate any feedback on this issue.

Thanks
Rahul

From: Gupta, Rahul
Sent: Friday, July 17, 2015 2:36 PM
To: users at lists.opensips.org
Subject: opensips taking 100% cpu

Hi,

I am using 1.11.3-tls version and opensips processes are taking 100% CPU.
PID      USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
12635 root      20   0  335m 1876 1068 R 100.0  0.0 335:02.96 opensips
12636 root      20   0  335m 1944 1140 R 100.0  0.0 335:03.71 opensips
12641 root      20   0  335m  88m  87m R 100.0  0.1 333:26.96 opensips
12645 root      20   0  335m  63m  62m R 100.0  0.1 333:23.76 opensips
12632 root      20   0  335m 1196  408 R 99.8  0.0  38:22.68 opensips
12647 root      20   0  335m  19m  18m R 99.8  0.0 561:16.07 opensips
12634 root      20   0  335m 1876 1068 R 99.5  0.0 333:22.10 opensips

None of the commands from opensipsctl are working, so I can't use opensipsctl trap to generate gbd info. I ran the gdb on couple of the PID and got the following back trace. Seems like opensips is stuck in some lock.

[root at sa-z2-ccm1 ~]# gdb /usr/sbin/opensips 12633
GNU gdb (GDB) Red Hat Enterprise Linux (7.2-60.el6_4.1)
Copyright (C) 2010 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /usr/sbin/opensips...done.
Attaching to program: /usr/sbin/opensips, process 12633
Reading symbols from /lib64/snoopy.so...done.
Loaded symbols for /lib64/snoopy.so
Reading symbols from /lib64/libdl.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libdl.so.2
Reading symbols from /lib64/libresolv.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libresolv.so.2
Reading symbols from /usr/lib64/libssl.so.10...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libssl.so.10
Reading symbols from /usr/lib64/libcrypto.so.10...(no debugging symbols found)...done.
Loaded symbols for /usr/lib64/libcrypto.so.10
Reading symbols from /lib64/libc.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libc.so.6
Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
Reading symbols from /lib64/libgssapi_krb5.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libgssapi_krb5.so.2
Reading symbols from /lib64/libkrb5.so.3...(no debugging symbols found)...done.
Loaded symbols for /lib64/libkrb5.so.3
Reading symbols from /lib64/libcom_err.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libcom_err.so.2
Reading symbols from /lib64/libk5crypto.so.3...(no debugging symbols found)...done.
Loaded symbols for /lib64/libk5crypto.so.3
Reading symbols from /lib64/libz.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libz.so.1
Reading symbols from /lib64/libkrb5support.so.0...(no debugging symbols found)...done.
Loaded symbols for /lib64/libkrb5support.so.0
Reading symbols from /lib64/libkeyutils.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libkeyutils.so.1
Reading symbols from /lib64/libpthread.so.0...(no debugging symbols found)...done.
[Thread debugging using libthread_db enabled]
Loaded symbols for /lib64/libpthread.so.0
Reading symbols from /lib64/libselinux.so.1...(no debugging symbols found)...done.
Loaded symbols for /lib64/libselinux.so.1
Reading symbols from /usr/lib64/opensips/modules/signaling.so...done.
Loaded symbols for /usr/lib64/opensips/modules/signaling.so
Reading symbols from /usr/lib64/opensips/modules/sl.so...done.
Loaded symbols for /usr/lib64/opensips/modules/sl.so
Reading symbols from /usr/lib64/opensips/modules/tm.so...done.
Loaded symbols for /usr/lib64/opensips/modules/tm.so
Reading symbols from /usr/lib64/opensips/modules/rr.so...done.
Loaded symbols for /usr/lib64/opensips/modules/rr.so
Reading symbols from /usr/lib64/opensips/modules/maxfwd.so...done.
Loaded symbols for /usr/lib64/opensips/modules/maxfwd.so
Reading symbols from /usr/lib64/opensips/modules/sipmsgops.so...done.
Loaded symbols for /usr/lib64/opensips/modules/sipmsgops.so
Reading symbols from /usr/lib64/opensips/modules/mi_fifo.so...done.
Loaded symbols for /usr/lib64/opensips/modules/mi_fifo.so
Reading symbols from /usr/lib64/opensips/modules/uri.so...done.
Loaded symbols for /usr/lib64/opensips/modules/uri.so
Reading symbols from /usr/lib64/opensips/modules/usrloc.so...done.
Loaded symbols for /usr/lib64/opensips/modules/usrloc.so
Reading symbols from /usr/lib64/opensips/modules/registrar.so...done.
Loaded symbols for /usr/lib64/opensips/modules/registrar.so
Reading symbols from /usr/lib64/opensips/modules/acc.so...done.
Loaded symbols for /usr/lib64/opensips/modules/acc.so
Reading symbols from /lib64/libnss_files.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libnss_files.so.2
0x00007fbea5ead527 in sched_yield () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install glibc-2.12-1.132.el6.x86_64 keyutils-libs-1.4-4.el6.x86_64 krb5-libs-1.10.3-33.el6.x86_64 libcom_err-1.41.12-18.el6.x86_64 libselinux-2.0.94-5.3.el6_4.1.x86_64 openssl-1.0.1e-30.el6.x86_64 zlib-1.2.3-29.el6.x86_64
(gdb) bt
#0  0x00007fbea5ead527 in sched_yield () from /lib64/libc.so.6
#1  0x00000000004b29cc in get_lock (send_sock=0x7fbea3a25398, type=2,
    buf=0x7fbea3a34ae8 "INFO sip:msml at 10.204.178.9:5069;transport=TCP SIP/2.0\r\nContent-Type: application/msml+xml\r\nTo: <sip:402649 at 10.204.178.9>;tag=10.204.178.95069+1+155c0002+eae86f8a\r\nVia: SIP/2.0/TCP 10.241.242.4:5060;br"..., len=864, to=0x7fffce949820, id=0) at fastlock.h:182
#2  tcpconn_get (send_sock=0x7fbea3a25398, type=2,
    buf=0x7fbea3a34ae8 "INFO sip:msml at 10.204.178.9:5069;transport=TCP SIP/2.0\r\nContent-Type: application/msml+xml\r\nTo: <sip:402649 at 10.204.178.9>;tag=10.204.178.95069+1+155c0002+eae86f8a\r\nVia: SIP/2.0/TCP 10.241.242.4:5060;br"..., len=864, to=0x7fffce949820, id=0) at tcp_main.c:900
#3  tcp_send (send_sock=0x7fbea3a25398, type=2,
    buf=0x7fbea3a34ae8 "INFO sip:msml at 10.204.178.9:5069;transport=TCP SIP/2.0\r\nContent-Type: application/msml+xml\r\nTo: <sip:402649 at 10.204.178.9>;tag=10.204.178.95069+1+155c0002+eae86f8a\r\nVia: SIP/2.0/TCP 10.241.242.4:5060;br"..., len=864, to=0x7fffce949820, id=0) at tcp_main.c:1088
#4  0x000000000042e469 in msg_send (send_sock=<value optimized out>, proto=<value optimized out>, to=0x7fffce949820, id=<value optimized out>,
    buf=0x7fbea3a34ae8 "INFO sip:msml at 10.204.178.9:5069;transport=TCP SIP/2.0\r\nContent-Type: application/msml+xml\r\nTo: <sip:402649 at 10.204.178.9>;tag=10.204.178.95069+1+155c0002+eae86f8a\r\nVia: SIP/2.0/TCP 10.241.242.4:5060;br"..., len=864) at forward.h:115
#5  0x000000000042ecfd in forward_request (msg=0x7fbea3a37018, p=0x7fbea3a37bd0) at forward.c:444
#6  0x0000000000415156 in do_action (a=0x7fbea3a310f8, msg=0x7fbea3a37018) at action.c:498
#7  0x00000000004137dc in run_action_list (a=<value optimized out>, msg=0x7fbea3a37018) at action.c:171
#8  0x000000000048de9f in eval_elem (e=0x7fbea3a311d8, msg=0x7fbea3a37018, val=0x0) at route.c:1618
#9  0x000000000048f7f3 in eval_expr (e=0x7fbea3a311d8, msg=0x7fbea3a37018, val=0x0) at route.c:1963
#10 0x000000000048f78a in eval_expr (e=0x7fbea3a31228, msg=0x7fbea3a37018, val=0x0) at route.c:1979
#11 0x000000000048f7b9 in eval_expr (e=0x7fbea3a31278, msg=0x7fbea3a37018, val=0x0) at route.c:1984
#12 0x0000000000416864 in do_action (a=0x7fbea3a31570, msg=0x7fbea3a37018) at action.c:1087
#13 0x00000000004137dc in run_action_list (a=<value optimized out>, msg=0x7fbea3a37018) at action.c:171
#14 0x0000000000413ae9 in run_actions (a=<value optimized out>, msg=<value optimized out>) at action.c:136
#15 0x00000000004190bc in do_action (a=0x7fbea3a2af60, msg=0x7fbea3a37018) at action.c:743
#16 0x00000000004137dc in run_action_list (a=<value optimized out>, msg=0x7fbea3a37018) at action.c:171
#17 0x0000000000419c93 in do_action (a=0x7fbea3a2bb28, msg=0x7fbea3a37018) at action.c:1105
#18 0x00000000004137dc in run_action_list (a=<value optimized out>, msg=0x7fbea3a37018) at action.c:171
#19 0x0000000000419c93 in do_action (a=0x7fbea3a2bce8, msg=0x7fbea3a37018) at action.c:1105
#20 0x00000000004137dc in run_action_list (a=<value optimized out>, msg=0x7fbea3a37018) at action.c:171
#21 0x000000000041c508 in run_actions (a=0x7fbea3a287d8, msg=0x7fbea3a37018) at action.c:136
#22 run_top_route (a=0x7fbea3a287d8, msg=0x7fbea3a37018) at action.c:211
#23 0x0000000000479c87 in receive_msg (buf=<value optimized out>, len=<value optimized out>, rcv_info=<value optimized out>) at receive.c:172
#24 0x00000000004dd771 in udp_rcv_loop () at udp_server.c:424
#25 0x0000000000437cd3 in main_loop (argc=<value optimized out>, argv=<value optimized out>) at main.c:942
#26 main (argc=<value optimized out>, argv=<value optimized out>) at main.c:1634

Any Ideas why is this happening ? I am running opensips with debug=2 mode and my logs are filled with the following messages

2015-07-17T08:54:02.000-04:00 [local2] [crit] sa-z2-ccm1.ipc.com /usr/sbin/opensips[12647]: CRITICAL:core:io_watch_del: invalid fd 5735, not in [0, 2189)
2015-07-17T08:54:02.000-04:00 [local2] [crit] sa-z2-ccm1.ipc.com /usr/sbin/opensips[12647]: CRITICAL:core:io_watch_del: invalid fd 5736, not in [0, 2189)
2015-07-17T08:54:02.000-04:00 [local2] [crit] sa-z2-ccm1.ipc.com /usr/sbin/opensips[12647]: CRITICAL:core:io_watch_del: invalid fd 5737, not in [0, 2189)
2015-07-17T08:54:02.000-04:00 [local2] [crit] sa-z2-ccm1.ipc.com /usr/sbin/opensips[12647]: CRITICAL:core:handle_io: uknown fd type -1549462248
2015-07-17T08:54:02.000-04:00 [local2] [crit] sa-z2-ccm1.ipc.com /usr/sbin/opensips[12647]: CRITICAL:core:handle_io: uknown fd type -1549462224
2015-07-17T08:54:02.000-04:00 [local2] [crit] sa-z2-ccm1.ipc.com /usr/sbin/opensips[12647]: CRITICAL:core:handle_io: uknown fd type -1549462176

Is this a known issue ? Any workarounds or fixes available for this ?

Thanks
Rahul Gupta

------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

DISCLAIMER: This e-mail may contain information that is confidential, privileged or otherwise protected from disclosure. If you are not an intended recipient of this e-mail, do not duplicate or redistribute it by any means. Please delete it and any attachments and notify the sender that you have received it in error. Unintended recipients are prohibited from taking action on the basis of information in this e-mail.E-mail messages may contain computer viruses or other defects, may not be accurately replicated on other systems, or may be intercepted, deleted or interfered with without the knowledge of the sender or the intended recipient. If you are not comfortable with the risks associated with e-mail messages, you may decide not to use e-mail to communicate with IPC. IPC reserves the right, to the extent and under circumstances permitted by applicable law, to retain, monitor and intercept e-mail messages to and from its systems.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20150721/4381bcaf/attachment-0001.htm>