21 Dec
2011
21 Dec
'11
2:27 a.m.
Hello everyone,
I'm doing some TLS performance testing on Kamailio 3.2.1. Here's my setup:
kamailio -V
version: kamailio 3.2.1 (x86_64/linux) 31c991
flags: STATS: Off, USE_IPV6, USE_TCP, USE_TLS, TLS_HOOKS,
USE_RAW_SOCKS, USE_STUN, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK,
SHM_MEM, SHM_MMAP, PKG_MALLOC, DBG_QM_MALLOC, USE_FUTEX,
FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR,
USE_DST_BLACKLIST, HAVE_RESOLV_RES
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16,
MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 4MB
poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
id: 31c991
compiled on 19:38:03 Dec 20 2011 with gcc 4.4.6
uname -a
Linux null.null.com 2.6.32-220.el6.x86_64 #1 SMP Tue Dec 6 19:48:22
GMT 2011 x86_64 x86_64 x86_64 GNU/Linux
CentOS 6.2 on a Dell PowerEdge R610 with 24 Intel X5650 Cores at
2.67GHz and 12GB of RAM (I could use more).
Kamailio is the default config with a few changes:
- WITH_TLS defined
- TLS is using self-generated CAs/certs (essentially openvpn easy-rsa)
with 1024 bit key size
- TLS is *not* configured to verify client OR server certs by default
- I'm using TLS v1 (SSL 3.1)
- TLS cipher suites are set to any (although my simulated UAs only
offer AES 256+SHA)
- Various changes to Kamailio children (up to 256 at times) and memory
sizes (up to 2048mb and even 4096mb at times)
- One DNS based alias added
- Maximum TCP connections increased to 65000
- Kamailio is configured to only listen on tested IP (UDP, TCP, TLS
sockets active)
- Syslog has been configured to log local0 (Kamailio) asynchronously
My test rig/call generator is an Ixia Xcellon-Ultra NP load module
with IXLoad. My call scenario does the following:
- Registers two simulated user agents (100000, 200000) to Kamailio with TLS
- Places call from 100000 to 200000 via Kamailio with TLS
- Increments both user agents by 1 and continues as quickly (cps) as I
like up to a channel limit (also configurable)
- The Ixia generates a valid SDP but no RTP is generated (although
that's certainly possible at these call levels)
Two 1 gig ports on the Ixia are connected to the Broadcom NICs on
the Dell R610 via a Cisco Catalyst 4948 switch. One port on the Ixia
emulates the 100000 agents (A leg) and the other emulates the 200000
agents (B leg). Of course I can provide more information if needed.
Here are some test numbers:
With TLS at 20cps, 120 sec calls, up to a total of 2470 calls (4940
registrations) life is good. Very good - call setup time averages
23ms, the cps rate holds indefinitely, and not a single call or
registration fails over long term tests.
UDP and TCP numbers are excellent (bordering ridiculous) - usually
around 500cps with practically no reasonable upper limit on
simultaneous calls. This doesn't need any further discussion :).
The TLS numbers start falling apart pretty quickly after 20cps,
however. If I change the TLS test to 40cps, 120 sec calls, up to a
total of 4940 calls (9,880 registrations) Kamailio starts to
(seriously) struggle. The rate starts fluctuating all over the place,
call setup time averages jump to 8000ms (or more) and things just
generally get ugly. Interestingly enough all of the user agents are
able to register, the logs look fine (to my eye at this log level) and
the system (CPU, network, etc) doesn't appear to be under stress at
all.
I have a few questions:
1) Is there something obviously wrong or stupid I'm doing here?
2) Why are the TLS tests so much worse than TCP and UDP? Am I
missing something here?
Thanks (in advance) for any advice anyone might be able to offer!
--
Kristian Kielhofner
21 Dec
21 Dec
3:20 a.m.
Hello,
On 12/20/11 10:27 PM, Kristian Kielhofner wrote:
Hello everyone,
I'm doing some TLS performance testing on Kamailio 3.2.1. Here's my setup:
kamailio -V
version: kamailio 3.2.1 (x86_64/linux) 31c991
flags: STATS: Off, USE_IPV6, USE_TCP, USE_TLS, TLS_HOOKS,
USE_RAW_SOCKS, USE_STUN, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK,
SHM_MEM, SHM_MMAP, PKG_MALLOC, DBG_QM_MALLOC, USE_FUTEX,
FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR,
USE_DST_BLACKLIST, HAVE_RESOLV_RES
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16,
MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 4MB
poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
id: 31c991
compiled on 19:38:03 Dec 20 2011 with gcc 4.4.6
uname -a
Linux null.null.com 2.6.32-220.el6.x86_64 #1 SMP Tue Dec 6 19:48:22
GMT 2011 x86_64 x86_64 x86_64 GNU/Linux
CentOS 6.2 on a Dell PowerEdge R610 with 24 Intel X5650 Cores at
2.67GHz and 12GB of RAM (I could use more).
Kamailio is the default config with a few changes:
- WITH_TLS defined
- TLS is using self-generated CAs/certs (essentially openvpn easy-rsa)
with 1024 bit key size
- TLS is *not* configured to verify client OR server certs by default
- I'm using TLS v1 (SSL 3.1)
- TLS cipher suites are set to any (although my simulated UAs only
offer AES 256+SHA)
- Various changes to Kamailio children (up to 256 at times) and memory
sizes (up to 2048mb and even 4096mb at times)
- One DNS based alias added
- Maximum TCP connections increased to 65000
- Kamailio is configured to only listen on tested IP (UDP, TCP, TLS
sockets active)
- Syslog has been configured to log local0 (Kamailio) asynchronously
My test rig/call generator is an Ixia Xcellon-Ultra NP load module
with IXLoad. My call scenario does the following:
- Registers two simulated user agents (100000, 200000) to Kamailio with TLS
- Places call from 100000 to 200000 via Kamailio with TLS
- Increments both user agents by 1 and continues as quickly (cps) as I
like up to a channel limit (also configurable)
- The Ixia generates a valid SDP but no RTP is generated (although
that's certainly possible at these call levels)
Two 1 gig ports on the Ixia are connected to the Broadcom NICs on
the Dell R610 via a Cisco Catalyst 4948 switch. One port on the Ixia
emulates the 100000 agents (A leg) and the other emulates the 200000
agents (B leg). Of course I can provide more information if needed.
Here are some test numbers:
With TLS at 20cps, 120 sec calls, up to a total of 2470 calls (4940
registrations) life is good. Very good - call setup time averages
23ms, the cps rate holds indefinitely, and not a single call or
registration fails over long term tests.
UDP and TCP numbers are excellent (bordering ridiculous) - usually
around 500cps with practically no reasonable upper limit on
simultaneous calls. This doesn't need any further discussion :).
The TLS numbers start falling apart pretty quickly after 20cps,
however. If I change the TLS test to 40cps, 120 sec calls, up to a
total of 4940 calls (9,880 registrations) Kamailio starts to
(seriously) struggle. The rate starts fluctuating all over the place,
call setup time averages jump to 8000ms (or more) and things just
generally get ugly. Interestingly enough all of the user agents are
able to register, the logs look fine (to my eye at this log level) and
the system (CPU, network, etc) doesn't appear to be under stress at
all.
I have a few questions:
1) Is there something obviously wrong or stupid I'm doing here?
2) Why are the TLS tests so much worse than TCP and UDP? Am I
missing something here?
with tls the limit is usually the cpu or memory, due to
encryption/decryption, but you say they look ok.
What log level are you using in config?
Is the test tool keeping the tls connections open or they are closed and
have to be open for each call? Can you spot if the delay is on incoming
side or on outgoing? Wireshark can decrypt the traffic if you provide
the certificate and start the sniffing before starting tls connections.
Alternative, set:
modparam("tls", "cipher_list", "NULL")
and the traffic should be no longer encrypted, but this will not show if
the bottleneck is the encryption process.
Also, benchmark module can help to see if execution of config file takes
longer than usual.
Jan Janak did tls tests some time ago, the summary is part of:
http://sip-router.org/wiki/performance/v3.0-capacity
I have some results from a test with 6000 SIP messages/sec over tls,
where CPU usage got about 60%. I guess something is becoming a
bottleneck in your case, very likely a blocking operation since cpu is
ok, just has to be discovered.
Cheers,
Daniel
--
Daniel-Constantin Mierla -- http://www.asipto.com
http://linkedin.com/in/miconda -- http://twitter.com/miconda
3:55 a.m.
On Tue, Dec 20, 2011 at 5:20 PM, Daniel-Constantin Mierla
<miconda(a)gmail.com> wrote:
Hello,
with tls the limit is usually the cpu or memory, due to
encryption/decryption, but you say they look ok.
What log level are you using in config?
Is the test tool keeping the tls connections open or they are closed and
have to be open for each call? Can you spot if the delay is on incoming side
or on outgoing? Wireshark can decrypt the traffic if you provide the
certificate and start the sniffing before starting tls connections.
Alternative, set:
modparam("tls", "cipher_list", "NULL")
and the traffic should be no longer encrypted, but this will not show if the
bottleneck is the encryption process.
Also, benchmark module can help to see if execution of config file takes
longer than usual.
Jan Janak did tls tests some time ago, the summary is part of:
http://sip-router.org/wiki/performance/v3.0-capacity
I have some results from a test with 6000 SIP messages/sec over tls, where
CPU usage got about 60%. I guess something is becoming a bottleneck in your
case, very likely a blocking operation since cpu is ok, just has to be
discovered.
Cheers,
Daniel
--
Daniel-Constantin Mierla -- http://www.asipto.com
http://linkedin.com/in/miconda -- http://twitter.com/miconda
Daniel,
Thank you for getting back to me so quickly.
The log level is the default (debug=2). I tried setting cipher_list
to NULL on client and server and now Kamailio has crashed (producing
core file) during the last seven tests. It seems I can get to about
1000 registered users before this happens. How should I provide a
backtrace?
Once I get past this issue I will try your other suggestions.
Thanks again!
--
Kristian Kielhofner
4:08 a.m.
On 12/20/11 11:55 PM, Kristian Kielhofner wrote:
On Tue, Dec 20, 2011 at 5:20 PM, Daniel-Constantin
Mierla
<miconda(a)gmail.com> wrote:
interesting,
let's see who is fault of that -- backtrace:
gdb /path/to/kamailio /path/to/corefile
- for short backtrace:
bt
- for full backtrace:
bt full
Provide both of them.
Cheers,
Daniel
--
Daniel-Constantin Mierla -- http://www.asipto.com
http://linkedin.com/in/miconda -- http://twitter.com/miconda
Hello,
with tls the limit is usually the cpu or memory, due to
encryption/decryption, but you say they look ok.
What log level are you using in config?
Is the test tool keeping the tls connections open or they are closed and
have to be open for each call? Can you spot if the delay is on incoming side
or on outgoing? Wireshark can decrypt the traffic if you provide the
certificate and start the sniffing before starting tls connections.
Alternative, set:
modparam("tls", "cipher_list", "NULL")
and the traffic should be no longer encrypted, but this will not show if the
bottleneck is the encryption process.
Also, benchmark module can help to see if execution of config file takes
longer than usual.
Jan Janak did tls tests some time ago, the summary is part of:
http://sip-router.org/wiki/performance/v3.0-capacity
I have some results from a test with 6000 SIP messages/sec over tls, where
CPU usage got about 60%. I guess something is becoming a bottleneck in your
case, very likely a blocking operation since cpu is ok, just has to be
discovered.
Cheers,
Daniel
--
Daniel-Constantin Mierla -- http://www.asipto.com
http://linkedin.com/in/miconda -- http://twitter.com/miconda
Daniel,
Thank you for getting back to me so quickly.
The log level is the default (debug=2). I tried setting cipher_list
to NULL on client and server and now Kamailio has crashed (producing
core file) during the last seven tests. It seems I can get to about
1000 registered users before this happens. How should I provide a
backtrace?
Once I get past this issue I will try your other suggestions.
6:58 a.m.
On Tue, Dec 20, 2011 at 6:08 PM, Daniel-Constantin Mierla
<miconda(a)gmail.com> wrote:
interesting, let's see who is fault of that -- backtrace:
gdb /path/to/kamailio /path/to/corefile
- for short backtrace:
bt
- for full backtrace:
bt full
Provide both of them.
Cheers,
Daniel
--
Daniel-Constantin Mierla -- http://www.asipto.com
http://linkedin.com/in/miconda -- http://twitter.com/miconda
Hi Daniel,
I've collected all of them and attached them to this message.
Let me know if there is anything else I can do.
Thanks!
--
Kristian Kielhofner
2:36 p.m.
Hello,
can you send also the last log messages (especially the ones before the
crash, printed by the same pid that wrote the core, there should be a
'BUG...' message)?
Looks like a double free in the libssl, what is your libssl version?
Cheers,
Daniel
On 12/21/11 2:58 AM, Kristian Kielhofner wrote:
On Tue, Dec 20, 2011 at 6:08 PM, Daniel-Constantin
Mierla
<miconda(a)gmail.com> wrote:
--
Daniel-Constantin Mierla -- http://www.asipto.com
http://linkedin.com/in/miconda -- http://twitter.com/miconda
interesting, let's see who is fault of that -- backtrace:
gdb /path/to/kamailio /path/to/corefile
- for short backtrace:
bt
- for full backtrace:
bt full
Provide both of them.
Cheers,
Daniel
--
Daniel-Constantin Mierla -- http://www.asipto.com
http://linkedin.com/in/miconda -- http://twitter.com/miconda
Hi Daniel,
I've collected all of them and attached them to this message.
Let me know if there is anything else I can do.
Thanks!
22 Dec
22 Dec
12:26 a.m.
On Wed, Dec 21, 2011 at 4:36 AM, Daniel-Constantin Mierla
<miconda(a)gmail.com> wrote:
Hello,
can you send also the last log messages (especially the ones before the
crash, printed by the same pid that wrote the core, there should be a
'BUG...' message)?
Looks like a double free in the libssl, what is your libssl version?
Cheers,
Daniel
Hi Daniel,
I don't see relevant lines in the log (surprisingly). The strange
part is there is always at least one kamailio process running when
this happens (or maybe not so strange).
This is an up to date CentOS 6 with openssl-1.0.0-20.el6.x86_64
installed. I do get this warning on startup (same on CentOS 5.x):
WARNING: tls [tls_init.c:587]: tls: openssl bug #1491 (crash/mem leaks
on low memory) workaround enabled (on low memory tls operations will
fail preemptively) with free memory thresholds 271581184 and 135790592
bytes
--
Kristian Kielhofner
12:56 a.m.
Hello,
On 12/21/11 8:26 PM, Kristian Kielhofner wrote:
On Wed, Dec 21, 2011 at 4:36 AM, Daniel-Constantin
Mierla
<miconda(a)gmail.com> wrote:
it has to be at least the message printed by:
LOG(L_CRIT, "BUG: qm_free: freeing already freed pointer,"
" first free: %s: %s(%ld) - aborting\n",
f->file, f->func, f->line);
Can you grep for it in logs?
The abort in frame #1 of bracktrace is triggered on purpose, at
mem/q_malloc.c line 458
Cheers,
Daniel
--
Daniel-Constantin Mierla -- http://www.asipto.com
http://linkedin.com/in/miconda -- http://twitter.com/miconda
Hello,
can you send also the last log messages (especially the ones before the
crash, printed by the same pid that wrote the core, there should be a
'BUG...' message)?
Looks like a double free in the libssl, what is your libssl version?
Cheers,
Daniel
Hi Daniel,
I don't see relevant lines in the log (surprisingly). The strange
part is there is always at least one kamailio process running when
this happens (or maybe not so strange).
This is an up to date CentOS 6 with openssl-1.0.0-20.el6.x86_64
installed. I do get this warning on startup (same on CentOS 5.x):
WARNING: tls [tls_init.c:587]: tls: openssl bug #1491 (crash/mem leaks
on low memory) workaround enabled (on low memory tls operations will
fail preemptively) with free memory thresholds 271581184 and 135790592
bytes
1:13 a.m.
On Wed, Dec 21, 2011 at 2:56 PM, Daniel-Constantin Mierla
<miconda(a)gmail.com> wrote:
it has to be at least the message printed by:
LOG(L_CRIT, "BUG: qm_free: freeing already freed pointer,"
" first free: %s: %s(%ld) - aborting\n",
f->file, f->func, f->line);
Can you grep for it in logs?
The abort in frame #1 of bracktrace is triggered on purpose, at
mem/q_malloc.c line 458
Cheers,
Daniel
--
Daniel-Constantin Mierla -- http://www.asipto.com
http://linkedin.com/in/miconda -- http://twitter.com/miconda
Hi Daniel,
I'm very sorry for missing this the first time around. There are
over 3GB of logs on this machine already (it's only been up for one
day).
I've attached the output of grep -i bug kamailio.log | gzip -c >
kamailio-bug.log.gz
Thanks again!
--
Kristian Kielhofner
16 May
16 May
3:55 a.m.
Hi,
I'm seeing similar issue in 3.1.0.. How did we fix it?
The back trace from my test is,
#2 0x0819c66c in qm_free (qm=0x7861c000, p=0x798fa2b0, file=0xb6f0b140
"tls: tls_init.c", func=0xb6f0bce0 "ser_free", line=296) at
mem/q_malloc.c:462
*#3 0xb6eec404 in ser_free (ptr=0x798fa2b0) at tls_init.c:296*
*#4 0xb72339ba in CRYPTO_free () from /lib/libcrypto.so.1.0.0*
#5 0xb72a7f64 in ?? () from /lib/libcrypto.so.1.0.0
#6 0xb72a813e in ERR_get_error () from /lib/libcrypto.so.1.0.0
#7 0xb6f0483e in tls_read_f (c=0x797fedb4, flags=0xbfe236d4) at
tls_server.c:1187
#8 0x08171e6e in tcp_read_headers (c=0x797fedb4, read_flags=0xbfe236d4) at
tcp_read.c:406
I appreciate if we could point the reason the for the double free.
Thanks
Jijo
On Wed, Dec 21, 2011 at 3:13 PM, Kristian Kielhofner <kris(a)kriskinc.com>wrote;wrote:
On Wed, Dec 21, 2011 at 2:56 PM, Daniel-Constantin
Mierla
<miconda(a)gmail.com> wrote:
it has to be at least the message printed by:
LOG(L_CRIT, "BUG: qm_free: freeing already freed pointer,"
" first free: %s: %s(%ld) - aborting\n",
f->file, f->func, f->line);
Can you grep for it in logs?
The abort in frame #1 of bracktrace is triggered on purpose, at
mem/q_malloc.c line 458
Cheers,
Daniel
--
Daniel-Constantin Mierla -- http://www.asipto.com
http://linkedin.com/in/miconda -- http://twitter.com/miconda
Hi Daniel,
I'm very sorry for missing this the first time around. There are
over 3GB of logs on this machine already (it's only been up for one
day).
I've attached the output of grep -i bug kamailio.log | gzip -c >
kamailio-bug.log.gz
Thanks again!
--
Kristian Kielhofner
_______________________________________________
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
sr-users(a)lists.sip-router.org
http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
17 May
17 May
3:08 a.m.
Hi Daniel,
Please let me know if you are aware about any fix on this issue.
Thanks
Jijo
On Tue, May 15, 2012 at 6:55 PM, Jijo <realjijo(a)gmail.com> wrote:
Hi,
I'm seeing similar issue in 3.1.0.. How did we fix it?
The back trace from my test is,
#2 0x0819c66c in qm_free (qm=0x7861c000, p=0x798fa2b0, file=0xb6f0b140
"tls: tls_init.c", func=0xb6f0bce0 "ser_free", line=296) at
mem/q_malloc.c:462
*#3 0xb6eec404 in ser_free (ptr=0x798fa2b0) at tls_init.c:296*
*#4 0xb72339ba in CRYPTO_free () from /lib/libcrypto.so.1.0.0*
#5 0xb72a7f64 in ?? () from /lib/libcrypto.so.1.0.0
#6 0xb72a813e in ERR_get_error () from /lib/libcrypto.so.1.0.0
#7 0xb6f0483e in tls_read_f (c=0x797fedb4, flags=0xbfe236d4) at
tls_server.c:1187
#8 0x08171e6e in tcp_read_headers (c=0x797fedb4, read_flags=0xbfe236d4)
at tcp_read.c:406
I appreciate if we could point the reason the for the double free.
Thanks
Jijo
On Wed, Dec 21, 2011 at 3:13 PM, Kristian Kielhofner <kris(a)kriskinc.com>wrote;wrote:
On Wed, Dec 21, 2011 at 2:56 PM,
Daniel-Constantin Mierla
<miconda(a)gmail.com> wrote:
it has to be at least the message printed by:
LOG(L_CRIT, "BUG: qm_free: freeing already freed pointer,"
" first free: %s: %s(%ld) - aborting\n",
f->file, f->func, f->line);
Can you grep for it in logs?
The abort in frame #1 of bracktrace is triggered on purpose, at
mem/q_malloc.c line 458
Cheers,
Daniel
--
Daniel-Constantin Mierla -- http://www.asipto.com
http://linkedin.com/in/miconda -- http://twitter.com/miconda
Hi Daniel,
I'm very sorry for missing this the first time around. There are
over 3GB of logs on this machine already (it's only been up for one
day).
I've attached the output of grep -i bug kamailio.log | gzip -c >
kamailio-bug.log.gz
Thanks again!
--
Kristian Kielhofner
_______________________________________________
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
sr-users(a)lists.sip-router.org
http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users
4383
days inactive
4531
days old
10 comments
3 participants
participants (3)
-
Daniel-Constantin Mierla -
Jijo -
Kristian Kielhofner