Possible performance bug

[Steve Grubb]

On Thursday 08 September 2005 21:44, Steve Grubb wrote:
> > Profiles would be helpful. Actually, it'd be interesting to see overhead
> > of audit turned on, but not generating any records (no rules loaded, no
> > avc messages).
>
> True. I'll see if we can get those.

OK, I do have some profile data from booting with profile=1. When audit was 
never enabled, the test ran in 22.6 seconds. When audit had run and been 
disabled, the test ran in 23.8 seconds. With audit enabled, the test took 
24.7 seconds. This is repeatable. 

Now some data...from audit not enabled:

 22579 total                                      0.0088
  2987 __d_lookup                                 4.1602
  2939 system_call                               58.7800
  2477 __link_path_walk                           0.5132
  2139 strncpy_from_user                         23.7667
  1129 inode_has_perm                             8.8898
  1120 avc_has_perm_noaudit                       5.3589
   959 kmem_cache_alloc                          13.1370
   913 kmem_cache_free                           19.4255
   807 dput                                       0.4667
   763 selinux_inode_permission                   4.6524
   731 _atomic_dec_and_lock                       2.2562
   614 memcpy                                    14.9756
   571 permission                                 3.1547
   485 __might_sleep                              2.8869

boot with audit, then disabled:
 23841 total                                      0.0093
  2729 strncpy_from_user                         30.3222
  2584 __d_lookup                                 3.5989
  2525 system_call                               50.5000
  2358 __link_path_walk                           0.4885
  1222 inode_has_perm                             9.6220
  1131 avc_has_perm_noaudit                       5.4115
  1103 kmem_cache_alloc                          15.1096
   995 kmem_cache_free                           21.1702
   752 memcpy                                    18.3415
   693 _atomic_dec_and_lock                       2.1389
   663 __might_sleep                              3.9464
   640 syscall_exit_work                         26.6667
   606 permission                                 3.3481
   591 dput                                       0.3418
   546 selinux_inode_permission                   3.3293
   511 avc_lookup                                 3.3399

And audit on:
 24672 total                                      0.0096
  3198 system_call                               63.9600
  2764 __d_lookup                                 3.8496
  2556 __link_path_walk                           0.5295
  1427 strncpy_from_user                         15.8556
  1303 kmem_cache_free                           27.7234
  1112 audit_syscall_exit                         0.8355
  1013 avc_has_perm_noaudit                       4.8469
   974 inode_has_perm                             7.6693
   974 _atomic_dec_and_lock                       3.0062
   812 kmem_cache_alloc                          11.1233
   665 dput                                       0.3846
   624 syscall_exit_work                         26.0000
   545 memcpy                                    13.2927
   464 selinux_inode_permission                   2.8293
   463 __might_sleep                              2.7560


The big difference between 1 & 2 is more kmem_cache_alloc & free, and 
syscall_exit_work. The syscall_exit_work comes from this test:

227         movl TI_flags(%ebp), %ecx
228         testw $_TIF_ALLWORK_MASK, %cx
229         jne syscall_exit_work

So, Amy is right, the TIF_AUDIT flag has some bearing on the benchmarks.

The big difference between runs 2 & 3 are _atomic_dec_and_lock being higher 
and audit_syscall_exit showing up. system_syscall was higher, too. Not sure 
where it picked up cycles. I think all of these increases are to be expected.

These are run with no rules loaded.

-Steve