FAPOLICYD.TIMING(5)

💖 FAPOLICYD.TIMING(5) 💖

okay bestie, so this is the manual page for fapolicyd.timing — it lives in the File Formats corner of the man universe, and it's literally just here to explain one very specific little report that fapolicyd(8) writes. sit with me, we're gonna get through it together 🫶

---

✨ NAME ✨

fapolicyd.timing — the manual decision timing report for fapolicyd. no cap, that's it. 🌸

---

🌈 DESCRIPTION 🌈

so the file /run/fapolicyd/fapolicyd.timing holds one manual decision timing run from fapolicyd(8). the daemon writes it when a privileged manual timing stop request ends an armed timing run. if a stop request comes in while timing isn't armed? it writes a short status report instead of the actual timing data. and the daemon can also stop collection and write the report on its own if a timing counter is about to overflow. 💀

timing collection is disabled by default, bestie. manual timing requests are only honored when the active daemon config has timing_collection=manual set in fapolicyd.conf(5). read that again, it matters.

the command fapolicyd-cli --timing-start arms a run, and fapolicyd-cli --timing-stop stops the run and prints this report. also --timer-start and --timer-stop are accepted aliases, in case that's the vibe you're on.

okay so here's the tea: the daemon stores aggregate counters only. it does not store one timing record per decision. each decision worker owns local aggregate blocks, and each block has a call count, total time, maximum time, and fixed latency buckets for each stage. the report just snapshots those blocks and aggregates them. iconic, efficient, we love to see it. ✨

---

👑 RUN SUMMARY 👑

the first lines summarize the run:

• Mode — the active timing collection mode.
• Timing run — wall-clock start and stop time.
• Duration — elapsed wall-clock run time, in H:MM:SS format.
• Workers — number of decision worker timing blocks included in the snapshot.
• Max queue depth — the highest internal event queue depth observed during the timing run. the daemon temporarily resets only the max queue depth counter when timing starts, and restores the previous high-water mark after timing stops if the previous value was larger. the Queueing section repeats this value right next to queue wait timing.
• Decisions — number of completed fanotify decisions timed during the run.
• Throughput — timed decisions per second over the wall-clock run duration. heads up, this includes time when fapolicyd was armed but no events were waiting to be decided. so yes it can look chill when it's actually just idle 🫠
• Active decision rate — timed decisions per second using the sum of decision:total latency instead of wall-clock duration. with more than one decision worker, this is worker-time, not elapsed wall-clock time. don't get it twisted.
• Stop reason — printed only when the run stopped automatically because a timing counter would overflow.

---

🎀 TL;DR 🎀

the TL;DR section shows up right after the run summary and before Overall decision latency. it surfaces two or three dominant findings drawn from the same data that the later Derived observations section uses — stuff like helper dominance, response formatting cost, or queueing health. the detailed observations stay in their original spot later in the report, so this is like the trailer, not the movie. 🍓

---

💜 OVERALL DECISION LATENCY 💜

the Overall decision latency section describes end-to-end decision latency, from the moment a decision worker starts processing a dequeued fanotify event until the decision path returns after response handling.

it prints average and maximum latency using compact latency units, approximate percentile buckets, and cumulative percentages for useful thresholds like <=50us, <=100us, <=500us, <=1ms, and >10ms. quick reality check: percentiles here are bucket approximations, not exact per-decision percentiles. the 95th percentile is a handy tail-latency marker though — roughly 95% of observed calls were at or below that bucket, so a high p95 points to a recurring slow path, not just one worst-case outlier doing main character energy. 😭

when high-end tail buckets are observed, the section also prints a compact tail line for >10ms, >25ms, >50ms, >100ms, and >250ms. the line includes both count and percentage, so long outliers don't just vanish inside a single >10ms bucket. bless. 🙏

---

🦋 QUEUEING 🦋

the Queueing section is all about work waiting before a decision worker starts processing an event. it's based on time_in_queue:total when enqueue timestamps were observed during the timing run.

• avg wait — average observed time in the internal userspace event queue.
• max wait — longest observed wait in the internal userspace event queue.
• p95 bucket — approximate bucket containing the 95th percentile queue wait.
• total queued time — sum of observed queue wait time. super useful for spotting producer/consumer imbalance, but ngl it is not decision CPU time, okay?
• max queue depth — highest internal event queue depth observed during the timing run.

if no enqueue timestamps were observed, the section prints not observed and still reports max queue depth. it shows up even when the data ghosted us. 💅

---

🧚 PER-WORKER TIMING SKEW 🧚

when more than one decision worker is active, the Per-worker timing skew section summarizes routing and latency balance by worker. the aggregate latency sections remain authoritative — this section exists just to make uneven worker buckets visible, like calling out who's not pulling their weight in the group project.

• decisions min/max/spread — smallest and largest number of timed decisions handled by any worker, plus the difference between them.
• Worker — decision worker index.
• Decisions — timed decisions handled by that worker.
• Total — sum of that worker's decision:total latency.
• Avg — average decision:total latency for that worker.
• Max — slowest decision:total latency for that worker.
• Queue p95 — approximate 95th percentile queue-wait bucket for that worker.

---

🔥 DECISION PHASE TIMING 🔥

the Decision phase timing section shows the main decision-thread phases when they were observed:

event_build:total
evaluation:total
response:total

• Phase — displayed phase name.
• Calls — number of times the phase was measured.
• Calls/Dec — average phase calls per timed decision.
• Total — total measured phase time.
• Avg — average phase call time.
• Max — slowest observed phase call.
• p95 bucket — approximate bucket containing the 95th percentile phase call.
• Notes — short deterministic notes. for example, a response phase dominated by syslog or debug formatting gets marked syslog/debug-heavy.

these phase rows are the best first view for explaining where decision-thread time is going. helper rows are kept separate because some lazy helper operations can be requested from more than one phase — they're not tied down to a single spot. 🦋

---

💅 LAZY HELPER ATTRIBUTION 💅

the report introduces helper attribution with this note, verbatim:

Lazy helper attribution:
  Helper timings are attributed to the active logical driver:
  evaluation or response.
  Combined totals are evaluation + response.

the driver table and combined helper table follow this note. so cute that it introduces itself first. ✨

---

🌸 LAZY HELPER ATTRIBUTION BY DRIVER 🌸

the Lazy helper attribution by driver section shows helper time split by the logical context that caused it: evaluation or response.

• Helper — short helper path.
• Eval total — total helper time caused while the rule evaluation driver was active.
• Response total — total helper time caused while response, audit metadata, or syslog/debug formatting was active.
• Combined — total helper time from all driver contexts.
• Response % — percentage of combined helper time caused by response-side work. this one is chef's kiss for deciding whether manual/debug reporting is driving MIME or trust lookup cost.

---

⭐ COMBINED LAZY HELPER ATTRIBUTION ⭐

the Combined lazy helper attribution section groups helper-related stages into stable combined paths. for helpers that are split by driver, the combined row is calculated by adding the phase-specific evaluation and response rows together. these rows answer two things: how often a helper was needed, and how expensive that helper was when amortized over all decisions. 🫶

• Helper path — short combined helper path.
• Calls — number of helper calls measured.
• Calls/Dec — average helper calls per timed decision.
• Total — total measured helper time.
• Avg/call — average measured helper call time.
• Amort/Dec — total helper time divided by all timed decisions. this shows how much a lazy or rare helper contributes to a typical decision in the measured workload.
• Max — slowest observed helper call.
• p95 bucket — approximate bucket containing the 95th percentile helper call.

and the current helper groups are, exactly:

mime_detection:total
mime_detection:fast_classification
mime_detection:gather_elf
mime_detection:libmagic_fallback
trust_db_lookup:total
trust_db_lookup:read
trust_db_lookup:lock_wait
hash_ima:total
hash_sha:total
proc_detail_lookup

---

🌈 DERIVED OBSERVATIONS 🌈

the Derived observations section prints short deterministic observations when the required data was present in the run. examples include:

• Wall-clock throughput compared with active decision rate, which can show that the workload was mostly idle while timing was armed. (not me arming a timer and then nothing happening 😭)
• Queue wait and maximum queue depth compared with q_size when queue timing and configuration data are available.
• Response formatting share when syslog/debug formatting dominates response:total.
• MIME helper cost and libmagic fallback share.
• Rare but expensive integrity work from hash_ima or hash_sha, reported as percent of decisions, average time when called, and amortized decision cost.
• Trust database lock wait compared with trust database read time.

---

🎀 STAGE TAIL SUMMARY 🎀

when hot detailed stage rows have observations above 10ms, the report prints a Stage tail summary after the detailed table. rows are sorted by >10ms count, limited to the top five rows, and extended with any additional row that has a nonzero >50ms count. near-identical parent/child tail rows may be suppressed to keep the section focused. it's giving curated. 💅

stage:name: >10ms count/percent, >25ms count/percent, >50ms count/percent

the detailed table remains the canonical total-time ranking — the tail summary only adds high-end resolution for rows that crossed one of the tail thresholds. thresholds with zero observations are omitted. no empty rows, no filler, periodt. ✨

💅 DETAILED STAGE TABLE

Okay so the Detailed stage timing table? By default it's sorted by total measured time, bestie. It's answering one very specific question: which measured operations ate the most total time during the run? This is the detailed girly view, and it is intentionally kept down here below the summary and the helper attribution sections. Deliberate placement, we respect it. 🫶

The decision:total row gets included when it's observed and it participates in the exact same total-time sort as everybody else. No special treatment, no VIP line. 👑

• Stage — the measured operation name. The current stage set is listed over in DECISION FLOW.
• Calls — how many times that operation got measured.
• Calls/Dec — average measured calls per timed decision.
• Total — total measured time for the stage.
• Avg — average measured call time for the stage.
• Max — the slowest observed call for that stage.
• p95 bucket — the approximate bucket containing the 95th percentile call for the stage.

Stages with zero calls are hidden from the table and listed under Not observed. If a stage is not observed, that means no measured call to that operation happened during the timing window. Example so it clicks: an absent evaluation:trust_db_lookup:total and response:trust_db_lookup:total line means no measured trust database lookup occurred from those drivers in that run. Not a bug. Just quiet. 🌸

---

🌈 DECISION FLOW

Stage names use a colon-separated hierarchy, like a little family tree:

phase:operation:child

Rows ending in :total are parent scopes. Child operation timings are useful contributors, but listen — they can be nested, lazy, or shared by more than one code path, so do not expect the child rows to add up to the parent total. They are not a receipt that balances. 😭

The main decision-thread view is:

decision:total
time_in_queue:total
event_build:total
event_build:cache_flush
event_build:proc_fingerprint
event_build:fd_stat

evaluation:lock_wait
evaluation:total
evaluation:mime_detection:total
evaluation:mime_detection:fast_classification
evaluation:mime_detection:gather_elf
evaluation:mime_detection:libmagic_fallback
evaluation:fd_path_resolution
evaluation:proc_detail_lookup
evaluation:hash_ima:total
evaluation:hash_sha:total
evaluation:trust_db_lookup:total
evaluation:trust_db_lookup:lock_wait
evaluation:trust_db_lookup:read

response:total
response:syslog_debug_format:total
response:mime_detection:total
response:mime_detection:fast_classification
response:mime_detection:gather_elf
response:mime_detection:libmagic_fallback
response:trust_db_lookup:total
response:trust_db_lookup:lock_wait
response:trust_db_lookup:read
response:audit_metadata:total
response:fanotify_write

Lazy helper operations get attributed to the active logical driver at the moment the helper is called. Rule evaluation uses evaluation:; response logging and audit response work use response:. And helper timing happening outside those logical drivers? That's treated as an instrumentation bug and it is not reported as a separate phase. We do not platform bugs here. 💀

---

🎀 STAGES

decision:total

Decision worker latency after a fanotify event has been dequeued. This wraps event build, policy evaluation, optional logging or audit preparation, and response handling. Queue wait time is reported separately — she has her own row, she doesn't share. ✨

time_in_queue:total

How long a fanotify event sat in the internal userspace queue between enqueue by the fanotify reader thread and dequeue by a decision worker. Heads up: events that were already chillin' in the queue when timing got armed don't have an enqueue timestamp, so they are not included in this stage. Sorry bestie, no timestamp no credit. 🙈

event_build:total

Construction of the internal event from fanotify metadata. This includes subject and object cache lookups, initial subject and object fingerprints, and some pattern-state work. Busy busy. 🐝

event_build:cache_flush

The object cache flush performed on the decision path when the global flush flag is set.

event_build:proc_fingerprint

The initial /proc/<pid> stat used to identify the subject process and to detect stale subject cache entries.

event_build:fd_stat

Stat of the fanotify file descriptor, used to fingerprint the object.

evaluation:lock_wait

Time spent waiting for the rule lock before policy evaluation. Yes she's waiting. Yes she's counting. 💅

evaluation:total

The rule list evaluation loop. Lazy subject, object, trust, hash, or type lookups caused by rule fields can show up as child operation timings and also contribute to this total. Double duty, iconic behavior.

evaluation:proc_detail_lookup

On-demand subject procfs detail lookups, including /proc/<pid>/status, /proc/<pid>/exe, subject executable type, session id, and auid lookups. These can be driven lazily by rules, by syslog/debug formatting, or by audit metadata. Very "who asked for this" energy, but in a good way. 🦋

evaluation:fd_path_resolution

Path resolution for the object file descriptor.

For the MIME and trust DB helper rows below, * means the driver prefix evaluation, response.

*:mime_detection:total

Object type and ELF/script detection.

*:mime_detection:fast_classification

In-house classification before the libmagic fallback. This includes empty-file, ELF/script, shebang, common magic number, common text format, and device checks. She's fast and she knows it. 🔥

*:mime_detection:gather_elf

The ELF/script header scan performed by gather_elf().

*:mime_detection:libmagic_fallback

The full libmagic fallback, used when the faster type checks cannot classify the object. The backup dancer who does get a solo sometimes. ⭐

evaluation:hash_ima:total

IMA digest collection from the security.ima xattr through get_ima_hash().

evaluation:hash_sha:total

SHA-style file digest collection through get_hash_from_fd2().

*:trust_db_lookup:total

Total trust database lookup through check_trust_database(). This includes update-thread lock wait, per-lookup LMDB read setup, the primary LMDB lookup, optional hash work requested by trust lookup, and the top-level /usr symlink retry path. She does it all. 👑

*:trust_db_lookup:lock_wait

Time spent waiting for the trust database update-thread lock before LMDB read setup. This is a future multi-decision-thread contention signal. Foreshadowing, lowkey. 👀

*:trust_db_lookup:read

LMDB read setup and trust database read work after the update-thread lock is held. Currently this includes per-lookup LMDB read transaction and cursor setup, the primary lookup, optional hash work requested by trust lookup, the top-level /usr symlink retry path, and read cleanup. A whole routine. 💖

response:total

Work after the rule loop has completed. This includes syslog/debug formatting, rule/source bookkeeping, decision metric updates, response selection, audit metadata preparation, fanotify response writes, and descriptor close work.

response:syslog_debug_format:total

Formatting of syslog or debug output after a decision. Lazy field lookups needed only for logging may appear as nested stage timings. Nested. Timings. It's giving layers. 🧚

response:audit_metadata:total

Preparation of fanotify audit response metadata before the response write. And when audit metadata needs object trust, trust lookup time can be nested here. Surprise guest appearance. ✨

response:fanotify_write

The actual write(2) of the fanotify response to the kernel. The moment of truth, fr fr.

---

📝 NOTES

The notes footer reports the largest queued-time contributor when queue wait was observed, the largest helper contributor, the largest decision phase contributor, and the slowest observed row by maximum time. Four little awards at the bottom. 🏆

For cache hit, miss, collision, eviction, subject deferral, and early subject eviction counters, go see fapolicyd.metrics(5).

⚠️ Real talk: if adding a timing count, total, or bucket counter would overflow, fapolicyd disarms timing, records an overflow stop reason, and writes the timing report — instead of letting counters wrap and skew the data. She would rather stop than lie to you. Periodt.

---

📁 FILES

• /run/fapolicyd/fapolicyd.timing — manual decision timing report.
• /run/fapolicyd/fapolicyd.state — runtime state report containing timing control state.
• /run/fapolicyd/fapolicyd.metrics — runtime metrics report containing cache counters.

---

👀 SEE ALSO

fapolicyd(8), fapolicyd-cli(8), fapolicyd.conf(5), fapolicyd.state(5), fapolicyd.metrics(5), and fapolicyd.trust(5).

---

And that's a wrap on part 2, bestie 🫶 this page is brought to you by Red Hat, dated May 2026, and filed under FAPOLICYD.TIMING(5) — go read your timing report, she's been waiting for you 💖🌸