Audit / Netlink slowness

[Bernardo Innocenti]

Hello,

on a server running kernel 2.6.11-1.1369_FC4, both ssh
and su where taking a longish amount of time (over >1.5 sec.)

Running "strace -r 2>strace.out su", I discovered that
netlink communication is the major cause of slowdown.

"su" connects to a NETLINK_AUDIT socket 3 or 4 times.
Each time it does 2 sendto() + recvfrom() operations,
with a latency of ~200ms.  This adds up to 800ms wasted
time.

Disabling CONFIG_AUDIT in the kernel makes su and ssh
very fast again.

Is this behavior to be expected?  CONFIG_AUDIT is enabled
by default, therefore many people are going to be hit by
this problem.

-- 
  // Bernardo Innocenti - Develer S.r.l., R&D dept.
\X/  http://www.develer.com/

[Steve G]

Hi,

> Running "strace -r 2>strace.out su", I discovered that
> netlink communication is the major cause of slowdown. 
netlink in theory should be fast. No routing or collisions.

> "su" connects to a NETLINK_AUDIT socket 3 or 4 times.
> Each time it does 2 sendto() + recvfrom() operations, 
It does an audit subsystem status to see if its enabled and if so a send of
auditable information. What version of pam, su, audit-libs, kernel are you using?

> with a latency of ~200ms.  This adds up to 800ms wasted
> time. 
Just out of curiosity, what cpu & clock speed do you have? Are you running UP or
SMP kernel? This code path should be entirely cpu bound as no io devices are
involved.

> Disabling CONFIG_AUDIT in the kernel makes su and ssh
> very fast again. 
You also lose part of your SE Linux avc messages. There was a deadlock condition
discovered and reported on the NSA SE Linux mail list. The solution was to move
part of the processing to syscall exit audit processing. With audit not compiled
in or enabled, you get an abreviated avc message under some conditions.

> Is this behavior to be expected? 
Not exactly. There will be a *some* delay as we've added a lot of new
functionality, but 800 ms total delay is excessive. I'll see if we can find the
culprit.

Thanks,
-Steve Grubb


		
__________________________________ 
Discover Yahoo! 
Use Yahoo! to plan a weekend, have fun online and more. Check it out! 
http://discover.yahoo.com/

[Bernardo Innocenti]

Steve G wrote:


> >Running "strace -r 2>strace.out su", I discovered
> that
> >netlink communication is the major cause of slowdown.
>  
>  netlink in theory should be fast. No routing or collisions. 
I suppose so, but I don't know any other netlink user
I could compare with to make sure it's really a problem
specific to audit.


> >"su" connects to a NETLINK_AUDIT socket 3 or 4 times.
> >Each time it does 2 sendto() + recvfrom() operations,
>  
>  It does an audit subsystem status to see if its enabled and if so a send of
>  auditable information. What version of pam, su, audit-libs, kernel are you using? 
 pam-0.79-10
 audit-libs-0.9.3-1
 coreutils-5.2.1-31
 kernel-2.6.11-1.1240_FC4

SELinux is disabled.

The kernel is a custom build with several drivers removed and
some debugging options turned off.  Should perform better than
stock kernels.


> >with a latency of ~200ms.  This adds up to 800ms wasted
> >time.
>  
>  Just out of curiosity, what cpu & clock speed do you have? 
It's an Athlon 2500 (3547.13 bogomips)


>  Are you running UP or SMP kernel? 
UP, with preemption disabled.


>  This code path should be entirely cpu bound as no io devices are
>  involved. 
Does the audit socket communication talk synchronously with
auditd?  If so, the problem could be there too.


> >Disabling CONFIG_AUDIT in the kernel makes su and ssh
> >very fast again.
>  
>  
>  You also lose part of your SE Linux avc messages. There was a deadlock condition
>  discovered and reported on the NSA SE Linux mail list. The solution was to move
>  part of the processing to syscall exit audit processing. With audit not compiled
>  in or enabled, you get an abreviated avc message under some conditions. 
I also disabled SELinux, mainly because I wasn't willing to
fix all my services to run properly with the strict policy that
was initially shipped with FC2.  Then I just didn't find the
time/motivation to turn it on again.  Yes, lame me :-)


> >Is this behavior to be expected?
>  
>  Not exactly. There will be a *some* delay as we've added a lot of new
>  functionality, but 800 ms total delay is excessive. I'll see if we can find the
>  culprit. 
Could you please also try an "strace -r" to make sure I'm
not the only one seeing this?

-- 
  // Bernardo Innocenti - Develer S.r.l., R&D dept.
\X/  http://www.develer.com/

[Colin Walters]

On Thu, 2005-06-16 at 03:56 +0200, Bernardo Innocenti wrote:

>  I also disabled SELinux, mainly because I wasn't willing to
>  fix all my services to run properly with the strict policy that
>  was initially shipped with FC2.  Then I just didn't find the
>  time/motivation to turn it on again.  Yes, lame me :-) 
You are aware things have massively changed since FC2?  It's
pretty easy to reenable, nowadays just run system-config-securitylevel
then reboot.

[Bernardo Innocenti]

Colin Walters wrote:
>  On Thu, 2005-06-16 at 03:56 +0200, Bernardo Innocenti wrote:
>  
>  
> >I also disabled SELinux, mainly because I wasn't willing to
> >fix all my services to run properly with the strict policy that
> >was initially shipped with FC2.  Then I just didn't find the
> >time/motivation to turn it on again.  Yes, lame me :-)
>  
>  
>  You are aware things have massively changed since FC2?  It's
>  pretty easy to reenable, nowadays just run system-config-securitylevel
>  then reboot. 
Yes, I do... but that's quite a complex server, with
some custom stuff installed in /usr/local, so I'm afraid
I'd have to fiddle with the policy.

Some time ago I bought O'Reilly's SELinux book and read
through it, but the underlying complexity of SELinux
scared me off somewhat.

I'm sure I can get it to work properly with my setup, but
I'm also afraid it would take too much headaches for initial
setup *and* some additional effort when I install new stuff.

That said, I'd recommend SELinux for most sites, expecially
when they are very popular.

-- 
  // Bernardo Innocenti - Develer S.r.l., R&D dept.
\X/  http://www.develer.com/

[Steve G]

> > netlink in theory should be fast. No routing or collisions.
>
> I suppose so, but I don't know any other netlink user
> I could compare with to make sure it's really a problem
> specific to audit. 
It works very similar to any other netlink app, except its unicast, synchronous,
and needs the netlink ack flag. This is because CAPP demands that if an event is
not able to be audited, use of the system should be denied. From pam's
perspective all that its concerned with is to send the audit event and see that
the kernel has taken custody of the event. At that point its free to continue. 

> >>"su" connects to a NETLINK_AUDIT socket 3 or 4
> times.
> >>Each time it does 2 sendto() + recvfrom() operations,
> > 
> > It does an audit subsystem status to see if its enabled and if so
> > a send of auditable information. What version of pam, su, audit-libs,
> > kernel are you using?
>
>  pam-0.79-10
>  audit-libs-0.9.3-1
>  coreutils-5.2.1-31
>  kernel-2.6.11-1.1240_FC4 
These are all good. I released a new audit package that has 2 syscalls removed.
You should see a performance improvement with audit-libs-0.9.5.

> > Just out of curiosity, what cpu & clock speed do you have?
>
> It's an Athlon 2500 (3547.13 bogomips) 
Good thanks. This is useful info.

> > This code path should be entirely cpu bound as no io devices are
> > involved.
>
> Does the audit socket communication talk synchronously with
> auditd?  If so, the problem could be there too. 
Yes. It also waits for the ack flag. It has absolutely got to know that the
kernel has the message. I did a review of the critical path in the kernel and
found a few minor improvements. I'm still looking at it and may have some more
improvements - but there's no big delay that I can see.

> >>Is this behavior to be expected?
> > 
> > Not exactly. There will be a *some* delay as we've added a lot 
> > of new functionality, but 800 ms total delay is excessive. I'll 
> > see if we can find the culprit.
>
> Could you please also try an "strace -r" to make sure I'm
> not the only one seeing this? 
I don't doubt your claims. I have made improvements with the assumption that your
results are reproducable. audit-libs-0.9.5 should behave better for you. I will
also release 0.9.6 today and see if I can get some timing information. I am using
a special kernel that has all the audit patches applied so my results may not
hold for a FC4 kernel.

Thanks for bringing this performance issue up.

-Steve Grubb


		
__________________________________ 
Discover Yahoo! 
Stay in touch with email, IM, photo sharing and more. Check it out! 
http://discover.yahoo.com/stayintouch.html

[Bernardo Innocenti]

Steve G wrote:

> >pam-0.79-10
> >audit-libs-0.9.3-1
> >coreutils-5.2.1-31
> >kernel-2.6.11-1.1240_FC4
>  
>  These are all good. I released a new audit package that has 2 syscalls removed.
>  You should see a performance improvement with audit-libs-0.9.5.
>
>  [...snip...]
>
>  I don't doubt your claims. I have made improvements with the assumption that your
>  results are reproducable. audit-libs-0.9.5 should behave better for you. I will
>  also release 0.9.6 today and see if I can get some timing information. I am using
>  a special kernel that has all the audit patches applied so my results may not
>  hold for a FC4 kernel. 
I'm testing again with latest audit-libs (0.9.7-1) and
a newer kernel (2.6.11-1.1383_FC5).

I'm happy to report that the strange delays I reported
are gone.  Commands like su and ssh are very fast now.

However, this is not the same machine I tested with the
first time.  It's an x86_64... and I also noticed that
I've compiled the kernel without CONFIG_AUDITSYSCALL.

I'm not sure if it may be important, but I can't reboot
right now, so I'll retest later.


>  Thanks for bringing this performance issue up. 
Thanks to *you* for fixing it!

-- 
  // Bernardo Innocenti - Develer S.r.l., R&D dept.
\X/  http://www.develer.com/

[Tyler Larson]

> >>Is this behavior to be expected?
> >
> >Not exactly. There will be a *some* delay as we've added a lot of new
> >functionality, but 800 ms total delay is excessive. I'll see if we can find the
> >culprit.
>  
>  
>  Could you please also try an "strace -r" to make sure I'm
>  not the only one seeing this?
>   
Here's one of the relevant parts of my strace -r (FC4, 1GHZ athalon).

What stands out to me is that is that the sendto() and recvfrom() operations 
aren't taking very long at all (remember, the relative time stamps are 
*between* system calls, not *elapsed* during system calls). And since 
recvfrom() is called with MSG_DONTWAIT, it's not going to block waiting for 
data. Instead, there's a 100ms sleep before each recvfrom() that really racks 
up the wait time. In total, I counted 9 places where su sleeps for 100ms 
before a recvfrom() -- so that's almost 1 sec killed just sleeping.

I haven't dug through the code yet (which package is it in, anyway?), but I 
can only imagine that the motivation for programming the thing like this (with 
nanosleep + recvfrom w/ MSG_DONTWAIT) is to limit the amount of time spent 
waiting for a reply. Obviously the reply takes *some* time to arrive, and 
calling recvfrom() without MSG_DONTWAIT wouldn't be a viable option--you might 
block forever. Hence, sleep long enough to give up a timeslice and hopefully 
let the reply be generated, then check to see if its there.

A more reasonable solution (assuming it's possible with NETLINK sockets--I 
don't know much about them) would be a select() with a maximum timeout of 
100ms. That gives you worst-case performance equal to what we see now, with 
the potential of much better.

Am I way off-base here, or does that sound like a good idea?

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

      0.000100 bind(3, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 0
      0.000543 fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
      0.000289 readlink("/proc/self/exe", "/bin/su", 4095) = 7
      0.000495 sendto(3, "\20\0\0\0\350\3\5\0\5\0\0\0\0\0\0\0", 16, 0, 
{sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 16
      0.000371 nanosleep({0, 100000000}, NULL) = 0
      0.101499 recvfrom(3, 
"0\0\0\0\350\3\0\0\5\0\0\0Ey\0\0\0\0\0\0\1\0\0\0\1\0\0\0"..., 1216, 
MSG_PEEK|MSG_DONTWAIT, {sa_family=AF_NETLINK, pid=0, groups=00000000}, [12]) = 48
      0.000428 nanosleep({0, 100000000}, NULL) = 0
      0.101554 recvfrom(3, 
"0\0\0\0\350\3\0\0\5\0\0\0Ey\0\0\0\0\0\0\1\0\0\0\1\0\0\0"..., 1216, 
MSG_DONTWAIT, {sa_family=AF_NETLINK, pid=0, groups=00000000}, [12]) = 48
      0.000438 sendto(3, "l\0\0\0\355\3\5\0\6\0\0\0\0\0\0\0PAM session 
open"..., 108, 0, {sa_family=AF_NETLINK, pid=0, groups=00000000}, 12) = 108
      0.000600 nanosleep({0, 100000000}, NULL) = 0
      0.101949 recvfrom(3, 
"$\0\0\0\2\0\0\0\5\0\0\0Ey\0\0\0\0\0\0\20\0\0\0\350\3\5"..., 1216, 
MSG_PEEK|MSG_DONTWAIT, {sa_family=AF_NETLINK, pid=0, groups=00000000}, [12]) = 36
      0.000444 recvfrom(3, 
"$\0\0\0\2\0\0\0\5\0\0\0Ey\0\0\0\0\0\0\20\0\0\0\350\3\5"..., 1216, 
MSG_DONTWAIT, {sa_family=AF_NETLINK, pid=0, groups=00000000}, [12]) = 36
      0.000442 close(3)                  = 0

[Steve G]

> Am I way off-base here, or does that sound like a good idea? 
Exactly right on. We can't wait forever in case kernel discards netlink packet
during a memory crunch or something else unforseen happens. The select loop will
work. It'll be in 0.9.7 later today.

Thanks,
-Steve Grubb


		
__________________________________ 
Discover Yahoo! 
Find restaurants, movies, travel and more fun for the weekend. Check it out! 
http://discover.yahoo.com/weekend.html

[Steve G]

> A more reasonable solution would be a select() with a maximum timeout
> of 
> 100ms. 
This has been implemented. It should be noticably faster. I put the new package
(0.9.7) in rawhide. Anyone interested in this problem should try it out. I will
probably push out a new audit package for FC4 next week after some testing
feedback.

Thanks,
-Steve Grubb


		
__________________________________ 
Yahoo! Mail Mobile 
Take Yahoo! Mail with you! Check email on your mobile phone. 
http://mobile.yahoo.com/learn/mail

[Steve G]

> "su" connects to a NETLINK_AUDIT socket 3 or 4 times.
> Each time it does 2 sendto() + recvfrom() operations,
> with a latency of ~200ms.  This adds up to 800ms wasted
> time. 
I see a way to get rid of 1 sendto and put it in the error path. This way people
without audit support (which would be rare for this distro) would get the extra
sendto. This would solve the common use problem. You really need audit compiled
in for SE Linux avc messages to be full and complete.

I also see a few *minor* issues in the kernel that might save a couple clock
cycles, but no magic bullet.

-Steve Grubb

__________________________________________________
Do You Yahoo!?
Tired of spam?  Yahoo! Mail has the best spam protection around 
http://mail.yahoo.com

[Bernardo Innocenti]

Steve G wrote:
> >"su" connects to a NETLINK_AUDIT socket 3 or 4 times.
> >Each time it does 2 sendto() + recvfrom() operations,
> >with a latency of ~200ms.  This adds up to 800ms wasted
> >time.
>  
>  
>  I see a way to get rid of 1 sendto and put it in the error path. This way people
>  without audit support (which would be rare for this distro) would get the extra
>  sendto. This would solve the common use problem. You really need audit compiled
>  in for SE Linux avc messages to be full and complete.
>  
>  I also see a few *minor* issues in the kernel that might save a couple clock
>  cycles, but no magic bullet. 
I could use this issue as an excuse to finally learn how
oprofile works.  Hopefully I'll be able to provide a
useful clue...

-- 
  // Bernardo Innocenti - Develer S.r.l., R&D dept.
\X/  http://www.develer.com/