SASL slow when selinux enabled

[Matthew B. Brookover]

It seems that sasl_server_start() takes 0.17 seconds to run with selinux
is disabled and takes 1.28 seconds to run when selinux is enabled.

The SASL mechanism is set to Kerberos 5.  The user is correctly
authorized, and except for sasl_server_start() being really slow, things
seem to work.

Does any one have any idea why this happens and how to fix it?

Some more details, the test system is running CentOS 6.3, which came
with Cyrus SASL 2.1.23 and MIT Kerberos 1.9 libraries.  I first noticed
the problem with OpenLDAP 2.4.28.  I have since compiled SASL 2.1.25 and
confirmed the problem using the sample client and sample server.

Running the sample client and sample server under strace, it looks like
sasl_server_start() opens and processes the same set of files 9 times.
Not sure why 9 times or why it would need to look at any of them more
then one time.

I grepped for open in the strace output collected while
sasl_server_start() was running and copied the last group of open calls
to get this list of files that are processed 9 times:

15:35:30.739312 open("/var/tmp/ldap_0", O_RDWR) = 12
15:35:30.748931 open("/etc/krb5.conf", O_RDONLY) = 13
15:35:30.749320 open("/dev/urandom", O_RDONLY) = 13
15:35:30.749664 open("/etc/krb5.conf", O_RDONLY) = 13
15:35:30.750056 open("/dev/urandom", O_RDONLY) = 13
15:35:30.750365 open("/dev/urandom", O_RDONLY) = 13
15:35:30.750700 open("/proc/self/task/4798/attr/current", O_RDONLY) = 13
15:35:30.750907 open("/proc/self/task/4798/attr/fscreate", O_RDONLY) = 13
15:35:30.751042 open("/etc/selinux/targeted/contexts/files/file_contexts.subs", O_RDONLY) = -1 ENOENT (No such file or directory)
15:35:30.751095 open("/etc/selinux/targeted/contexts/files/file_contexts", O_RDONLY) = 13
15:35:30.751199 open("/etc/selinux/targeted/contexts/files/file_contexts.homedirs", O_RDONLY) = 14
15:35:30.751251 open("/etc/selinux/targeted/contexts/files/file_contexts.local", O_RDONLY) = -1 ENOENT (No such file or directory)
15:35:30.873405 open("/proc/self/task/4798/attr/current", O_RDONLY) = 13
15:35:30.873964 open("/proc/self/task/4798/attr/fscreate", O_RDWR) = 13
15:35:30.874148 open("/usr/local/etc/openldap/ldap-infinite-temp.keytab", O_RDONLY) = 13
15:35:30.874228 open("/proc/self/task/4798/attr/current", O_RDONLY) = 14
15:35:30.875398 open("/proc/self/task/4798/attr/fscreate", O_RDWR) = 14

There are also many repeated calls to read, mmap, brk, and others that
repeat 9 times while sasl_server_start() is running.

So far, I have only tinkered with the sample/server.c code and tracked
the slowness to sasl_server_start().

With selinux disabled, it seems that sasl_server_start() does similar
looping with krb5.conf, /etc/hosts, etc.  The loop is still there, but,
it does not take long because selinux is not slowing things way down.

Kinit, ksu, ssh, and other "kerberized" programs do not seem to have any
performance problems on CentOS 6.3.  I have only noticed the slow down
on programs that use SASL with saslauthd running on a system with
selinux enabled.

I appreciate any ideas you may have.

Thanks

Matt
mbrookov at mines.edu


-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.andrew.cmu.edu/pipermail/cyrus-sasl/attachments/20120910/babc3ec0/attachment.html