lkml.org 
[lkml]   [2022]   [Sep]   [27]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
From
Subject[PATCH 0/3] improve audit syscall-exit latency
Date
This series attempts to reduce syscall-exit latency in the audit path,
especially for cases where there are a lot of audit exit rules.

From profiling, audit_filter_syscall() takes the largest chunk of time,
specifically in this list-walk while processing the AUDIT_FILTER_EXIT
list:

list = &audit_filter_list[AUDIT_FILTER_EXIT];

list_for_each_entry_rcu(e, list, list) {
if (audit_in_mask(&e->rule, ctx->major) &&
audit_filter_rules(tsk, &e->rule, ctx, NULL,
&state, false, x)) {
rcu_read_unlock();
ctx->current_state = state;
return state;
}
}

(Note that almost identical logic exists in audit_filter_uring(),
audit_filter_inode_name().)

Comparing baseline performance with audit=0/audit=1 with a user-space
getpid() loop (executes 10^7 times.) For audit=1, this uses an
audit-rule set where the audit_filter_syscall() loop iterates over
42 AUDIT_FILTER_EXIT rules which, for getpid(), calls audit_filter_rules()
for 5 of them (we use this set of rules in production.)

Test system:
Server: ORACLE SERVER X8-2L
CPU: Intel Skylakex (6:85:6)
Microcode: 0x400320a

# v6.0.0-rc5.baseline, audit=0
Performance counter stats for 'bin/getpid' (3 runs):

734.10 msec task-clock # 0.999 CPUs utilized ( +- 0.03% )
1 context-switches # 1.361 /sec ( +- 66.67% )
0 cpu-migrations # 0.000 /sec
53 page-faults # 72.152 /sec ( +- 0.63% )
2,838,869,156 cycles # 3.865 GHz ( +- 0.01% ) (62.40%)
4,174,224,305 instructions # 1.47 insn per cycle ( +- 0.01% ) (74.93%)
890,798,133 branches # 1.213 G/sec ( +- 0.01% ) (74.93%)
5,015,118 branch-misses # 0.56% of all branches ( +- 0.05% ) (74.93%)
1,231,150,558 L1-dcache-loads # 1.676 G/sec ( +- 0.01% ) (74.94%)
418,297 L1-dcache-load-misses # 0.03% of all L1-dcache accesses ( +- 0.68% ) (75.07%)
3,937 LLC-loads # 5.360 K/sec ( +- 3.76% ) (50.13%)
510 LLC-load-misses # 13.39% of all LL-cache accesses ( +- 79.89% ) (50.00%)

0.735018 +- 0.000275 seconds time elapsed ( +- 0.04% )

# v6.0.0-rc5.baseline, audit=1
Performance counter stats for 'bin/getpid' (3 runs):

2,158.81 msec task-clock # 0.998 CPUs utilized ( +- 0.13% )
2 context-switches # 0.925 /sec ( +- 28.87% )
0 cpu-migrations # 0.000 /sec
52 page-faults # 24.056 /sec ( +- 0.64% )
8,364,119,898 cycles # 3.869 GHz ( +- 0.11% ) (62.48%)
19,996,521,678 instructions # 2.39 insn per cycle ( +- 0.01% ) (74.98%)
4,302,068,252 branches # 1.990 G/sec ( +- 0.00% ) (74.98%)
15,135,694 branch-misses # 0.35% of all branches ( +- 0.16% ) (74.99%)
4,714,694,841 L1-dcache-loads # 2.181 G/sec ( +- 0.01% ) (74.99%)
66,407,857 L1-dcache-load-misses # 1.41% of all L1-dcache accesses ( +- 1.50% ) (75.01%)
6,785 LLC-loads # 3.139 K/sec ( +- 12.49% ) (50.03%)
3,235 LLC-load-misses # 41.29% of all LL-cache accesses ( +- 6.08% ) (50.01%)

2.16213 +- 0.00288 seconds time elapsed ( +- 0.13% )

perf stat numbers for each getpid() iteration:

baseline baseline
audit=0 audit=1

cycles 283 836
instructions 417 1999
IPC 1.47 2.39
branches 89 430
branch-misses 0.50 1.51
L1-loads 123 471
L1-load-misses ~0 ~6.6*

* the L1-load-misses are largely stable for runs across a single
boot, but vary across boots due to vagaries of the SLAB allocator.

baseline audit=1 spends a significant amount of time executing in audit
code and incurs a new branch-miss and a few new L1-load-misses. Also
note that computed audit-only IPC is 2.86 so the baseline is not
ill-performant code.

Patches
==

Patch 1 "audit: cache ctx->major in audit_filter_syscall()", caches
ctx->major in a local variable. This gets rid of a persistent entry
from L1-dcache (audit_context::major) that had similar alignment
constraints as a potentially busy cache-set (audit_entry::list) and
allows some of the error checking in audit_in_mask() to be hoisted out
of the loop.

Patch 2: "audit: annotate branch direction for audit_in_mask()", so
the compiler can pessimize the call to audit_filter_rules().

Patch 3, "audit: unify audit_filter_{uring(),inode_name(),syscall()}"
centralizes this logic in a common function.

with these changes:

Performance counter stats for 'bin/getpid' (3 runs):

1,750.21 msec task-clock # 0.994 CPUs utilized ( +- 0.45% )
3 context-switches # 1.705 /sec ( +- 11.11% )
0 cpu-migrations # 0.000 /sec
52 page-faults # 29.548 /sec ( +- 0.64% )
6,770,976,590 cycles # 3.848 GHz ( +- 0.40% ) (27.74%)
16,588,372,024 instructions # 2.44 insn per cycle ( +- 0.03% ) (33.34%)
4,322,555,829 branches # 2.456 G/sec ( +- 0.02% ) (33.40%)
2,803,286 branch-misses # 0.06% of all branches ( +- 26.45% ) (33.46%)
4,449,426,336 L1-dcache-loads # 2.528 G/sec ( +- 0.01% ) (27.71%)
63,612,108 L1-dcache-load-misses # 1.43% of all L1-dcache accesses ( +- 0.50% ) (27.71%)
6,123 LLC-loads # 3.479 K/sec ( +- 8.68% ) (27.71%)
1,890 LLC-load-misses # 26.69% of all LL-cache accesses ( +- 46.99% ) (27.71%)

1.76033 +- 0.00791 seconds time elapsed ( +- 0.45% )

And, overall getpid() latency numbers (aggregated over 12 boots for each):
Min Mean Median Max pstdev
(ns) (ns) (ns) (ns)

baseline 201.30 216.14 216.22 228.46 (+- 1.45%)
patch1 196.63 207.86 206.60 230.98 (+- 3.92%)
patch1-2 173.11 182.51 179.65 202.09 (+- 4.34%)
patch1-3 162.11 175.26 173.71 190.56 (+- 4.33%)

This gives a reasonable speedup. My testing was on Intel Skylake, but I
suspect this should translate to other archs as well (especially on less
wide architectures.)

Please review.

Thanks
Ankur

Ankur Arora (3):
audit: cache ctx->major in audit_filter_syscall()
audit: annotate branch direction for audit_in_mask()
audit: unify audit_filter_{uring(),inode_name(),syscall()}

kernel/auditsc.c | 86 +++++++++++++++++++++++++-----------------------
1 file changed, 45 insertions(+), 41 deletions(-)

--
2.31.1

\
 
 \ /
  Last update: 2022-09-28 01:01    [W:0.151 / U:0.164 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site