Watch Performance

Hello,

Over the last day or two, I re-worked the user space audit code to be able to control the new file system audit subsystem. As I was doing the work, I became concerned about the performance impact since it appears to be using the syscall exit filter.

The syscall exit filter (and entry filter) is expensive to use except in cases where you need to use it. This is because each rule in it must be examined during each syscall to see if the current syscall is of interest. The current lspp configuration has 10 syscall audit rules.

I became curious what the measured impact would be with the current file system audit implementation. I decide to run the same performance test that I tested the audit system with a couple weeks ago when inode and IPC problems were noticed. I used the lspp.16 kernel with profile=2 boot param. The following table shows the results:

rules seconds
0 49

10      56
25      75
50      115
75      143
90      185

0 rules had this for function usage:

1284 __d_lookup 4.7380
1170 __link_path_walk 0.3098
1065 avc_has_perm_noaudit 1.2144
706 _atomic_dec_and_lock 8.4048
612 do_path_lookup 0.8204
561 dput 1.2986
509 _raw_spin_lock 2.1477

10 rules had this:

  1295 __d_lookup                                 4.7786
  1089 audit_filter_syscall                       6.3684
  1081 __link_path_walk                           0.2862

889 avc_has_perm_noaudit 1.0137
676 audit_getname 2.6000
658 do_path_lookup 0.8820
596 _atomic_dec_and_lock 7.0952

25 rules had this:

3193 audit_filter_rules 3.0009
2178 audit_filter_syscall 12.7368
1280 __d_lookup 4.7232
1131 __link_path_walk 0.2994
956 avc_has_perm_noaudit 1.0901
652 _atomic_dec_and_lock 7.7619
530 dput 1.2269

50 rules had this:

11213 audit_filter_rules 10.5385
4654 audit_filter_syscall 27.2164
4100 selinux_task_ctxid 141.3793
1212 __d_lookup 4.4723
1103 __link_path_walk 0.2920
1012 avc_has_perm_noaudit 1.1539
788 _atomic_dec_and_lock 9.3810

75 had this:

 15351 audit_filter_rules                        14.4276
  6032 audit_filter_syscall                      35.2749
  2066 selinux_task_ctxid                        71.2414

1237 __d_lookup 4.5646
1184 __link_path_walk 0.3135
1014 avc_has_perm_noaudit 1.1562
592 _atomic_dec_and_lock 7.0476

and 90 rules had this:

18287 audit_filter_rules 17.1870
9173 audit_filter_syscall 53.6433
4346 selinux_task_ctxid 149.8621
1314 __link_path_walk 0.3479
1218 __d_lookup 4.4945
1070 avc_has_perm_noaudit 1.2201
682 _atomic_dec_and_lock 8.1190

As you can see, the audit_filter_rules and audit_filter_syscall overwhelmed the profile quickly. It would not be unreasonable for a system to have 40 watches. The lspp rules have 56 of them. With 10 syscall rules added, the performance of a correctly configured lspp machine will be similar to the 75 rules test. This represents a 186% performance hit compared to no audit rules.

I do not believe optimizing the audit_filter_rules function will solve the problem. I think the file system audit algorithm needs to be re-thought. It simply cannot penalize every syscall.

There are several ways to solve the problem. Maybe what we need to do is use the watch list to store watches on and add a new field to the context. If a watch is triggered it sets the flag in the context. When syscall exit is done, it checks the flag and if set, does both the watch list and the exit list. Otherwise, it skips the watch list. I don't know if this is feasible, or a preferred solution, but we need to start looking at how to decouple the exit list and watches.

-Steve

Hi,

Based on finding an unnecessary function call to selinux_task_ctxid when evaluating syscall rules, I built a new kernel and re-ran the same tests.

rules  seconds loss
0        47 0%

10      53            11%
25      68            43%
50      99            109%

75      132 178%
90      157 232%

The 75 rule performance hit is now 178% instead of 184%. So there is some notable improvement in performance.

For comparison, I also loaded the 90 rules config into RHEL4. There is only a 6% performance hit compared to no rules. I think the bulk of that comes from evaluating the 10 syscall rules rather than the file system audit code.

-Steve

In case anyone else wants to run the same tests I did, you can download the program from http://people.redhat.com/sgrubb/files/watch-perf.tar.gz. Unpack the tarball and look for a README file which explains the setup steps.

-Steve

Steve,

In order for these numbers to be meaningful, a little more information is needed:

1) what audit rules did you use?
2) what system call(s) did you measure?

Steve Grubb wrote: [Sat Apr 08 2006, 12:21:57PM EDT]

3) how many operations were completed in N seconds?

I used the lspp rules to get the 1st 10, and the rest were against files in /etc/test.

access("/usr/include", 0);

The watch rules were never triggered because I wanted to measure the overhead where no audit events occur. The syscall exercises the file system without doing any IO, which would complicate things, too.

-Steve

I took a look at the rules lists in the tarball you sent. The rules are not specified in a way that makes sense with what you are measuring.

The watches are added with the -w syntax. In auditctl, this translates to setting an "all" syscall rule.

OK, I re-worked auditctl to use these syscalls instead of "all". I then re-ran the tests on the same kernel as I was testing on since lspp.17 has slab debug stuff turned on again.

rules seconds loss
0 50 0%

10      52            4%
25      56            12%
50      69            38%
75      81            62%
90      87            74%

The 75 rule performance hit is now 62%. So there is some improvement in performance. RHEL4 has a 6% hit for 90 rules. We've narrowed the difference, but I don't consider this solved.

I also don't like the idea of handling this by all those syscalls or using "all" because user space tools could get out of sync with the kernel. On any kernel upgrade, there could be a new syscall that allows file system access. The user space tools wouldn't know about it and wouldn't provide automatic coverage.

-Steve

Maybe we ought to have a way to specific all system calls of a particular type and let the kernel audit code decides which ones those are. We could group file operations, mode changes, ownership changes, privilege changes, execs, time changes, etc. That way admins don't necessarily have to know all the different ways one might do a chown, lchown, fchown, etc. And maybe there should be an 'all' that really means 'all' and not just all that the user space tools know about.

-- ljk

Steve Grubb wrote: [Tue Apr 11 2006, 05:01:23PM EDT]

Hmm, that's interesting, thanks.

Do you mean 10 rules + 80 watches? Or 90 rules?

I think there are three syscall groups for which we want to consider the performance impact of having a large number of rules.

1. syscalls for which there are no rules

In most use cases, the majority of syscalls will fall into this group. That makes this group the most important because it likely has the most effect on general system performance. Based on your numbers above, it looks like the impact here is unacceptable.

For this group, there should be no filtering overhead at all. To achieve this, we must have some indication per-list whether there are any rules for a given syscall. If there are no rules for the syscall, don't even walk the list.

2. syscalls for which there are a small number of rules

For this group we must walk the list, and some filtering overhead is acceptable. How much overhead is acceptable is a factor of how many syscalls we would typically expect to be in this group, and how often we would expect those syscalls to be used.

If we need to optimize for this case, we have a couple of options.

a) Provide features which reduce the number of rules for a heavy offender. E.g. for filesystem auditing,

- allow multiple watches per rule, akin to multiple inodes per rule
- allow a single watch on a directory to apply to many files

b) Separate the rules for a heavy offender, e.g. by putting them in a separate list

3. syscalls for which there are a large number of rules

For this group, the filtering overhead is the most significant and optimization is more difficult. For some use cases, having a rules tree instead of a rules list might help.

For filesystem auditing, when you want to audit a large number of inodes or watches, being able to audit an entire sub-tree with a single rule would help that particular use case. However, if you want to audit specific inodes/watches that are spread throughout a filesystem, the syscall-exit-based filtering is always going to exact a penalty.

The only way I can think of to mitigate this is to hang the rule data off of the inodes themselves, and receive a callback for each filesystem event. You can do the filtering from the callback, and eliminate the list traversal on syscall exit.

This is basically the RHEL4 implementation, and there are a few reasons why we can't do it this way right now. The first reason is that inotify is doing something similar, and we need to attempt to consolidate similar pieces of kernel functionality. Inotify, however, does not support all of the filesystem events we care about auditing. Additionally for those events that inotify does support, its hooks are placed in such a way that events are not produced for failed operations (which we care about).

To use this type of implementation in audit, we must be able to either significantly extend inotify, or justify our need for having our own implementation to kernel.org. I think the former is more preferable than the latter.

Yes, it makes the rules long and ugly.

Auditctl could support keywords on the command line that map to various groups of system calls. That would be more user-friendly.

True, we would have to keep an eye on new syscalls.

Hope this helps,
Amy

Hi,

Maybe this is a completely stupid thought, but what about the option of adding a per-syscall filter list table, indexed by system-call number. When the system-call occurs, say open(), we then:

1) Check if list_empty(filter_table.entry/exit[5]), if empty, no filter rules for open(), exit.

2) Otherwise, we walk the list... and we're only walking a list of filter rules that apply to open().

There's a space consumption penalty here... I dunno, I've been out of the game for some time now. Just a thought.

-tim

That's how LAuS worked... You'd need to support multiple lists to handle multiple personalities (ie 32bit code running on x86_64).

The amount of space used isn't too bad; it would also be possible to use reference counting to share entries for identical rules.

-Klaus

Klaus Weidner wrote: [Mon Apr 17 2006, 04:06:56PM EDT]

This approach makes a lot of sense to me. I think it would be a good next-step for audit filtering.

Al, proposed a different solution. You might want to check with him for details. It was discussed at the Monday Telecon.

-Steve

Maybe Al could post something? With the buzz on the phone line some of the discussion was hard to follow.

-- ljk

Basically, add 3 families of rule lists. Rule that has one AUDIT_INODE or AUDIT_WATCH field and would currently sit in audit_filter_list[n] would be moved to audit_filter_list[AUDIT_NR_FILTERS + n * 31 + ino % 31] where ino is inode number from the AUDIT_INODE/AUDIT_WATCH field of that rule. Everything else would remain where it is now.

If ->ino changes during the lifetime, rule would have to be moved between these lists.

When we are trying to match context with rules on (current) list #n, we _know_ that many of them won't match just on the grounds of ->ino mismatch. With that splitting of lists we can skip most of those - rules from the current list #n will be on list #n and 31 lists starting with AUDIR_NR_FILTERS + 31*n. We only need to scan

	n (that's where non-watch rules remain)
	AUDIT_NR_FILTERS + 31*n + ctx->names[i].ino % 31 for each i less than

ctx->name_count.

Everything else is not going to match and doesn't have to be looked at.

Alexander Viro wrote: [Fri Apr 21 2006, 12:07:52PM EDT]

While the per-syscall lists would be a good overall improvement to audit filtering, this better solves the specific problem of many inode-based rules.

Since inodes are only applicable to the syscall exit filter list, it could be simplified to use a single inode-based hash, instead of one for each filterlist (AUDIT_NR_FILTERS).

I'd be happy to add this functionality as a follow-on patch to the filesystem auditing patch, if no one else is working on it.

Amy

I re-ran the analysis with the lspp.24 kernel. This is the results:

rules seconds loss
0 57.4 0.0%

10      57.8           0.7%
25      56.7         +1.2%
50      58.6           2.1%
75      59.7           4.0%
90      59.1           3.0%

The results look good for this test case. Thanks to everyone that helped solve this problem! Good job.

-Steve

--
redhat-lspp mailing list
[email protected]
https://www.redhat.com/mailman/listinfo/redhat-lspp

Hrm... Results do look good, but I wonder what had given us >10% loss in the baseline. Would be nice if somebody rerun the tests with 0 rules on lspp.24 and whatever had been used to generate original numbers and did it with profiling enabled. If this difference is real, it should show up in profiles in enough details...

I have that data. Original:

  1295 __d_lookup                                 4.7786
  1286 __link_path_walk                           0.3405
   798 avc_has_perm_noaudit                       0.9099
   701 _atomic_dec_and_lock                       8.3452
   521 audit_getname                              2.0038
   513 do_path_lookup                             0.6877
   377 _raw_spin_lock                             1.5907
   351 dput                                       0.8125
   340 kmem_cache_free                            1.0059
   265 strncpy_from_user                          2.2845
   265 inode_has_perm                             2.6768
   263 _raw_read_lock                             1.6646

Latest:

  1376 __d_lookup                                 5.0588
  1104 __link_path_walk                           0.2803
   997 avc_has_perm_noaudit                       1.1368
   940 do_path_lookup                             1.2617
   677 _atomic_dec_and_lock                       7.6932
   627 _raw_spin_lock                             2.6456
   448 dput                                       1.0370
   421 kmem_cache_free                            1.1566
   417 inode_has_perm                             4.2121
   386 audit_getname                              1.4846
   381 link_path_walk                             1.6638
   333 audit_syscall_exit                         0.3927

I think do_path_lookup & _raw_spin_lock jump out as the biggest changes.

-Steve

That's very odd. I can at least understand where spinlock crap might appear, but nearly doubled amount of do_path_lookup()? That's the case when no watches are set, right?

Right. No watches or syscall rules.

-Steve