skip to content

A hook added with sys.addaudithook slowed a 6-hour nightly ETL export and then aborted it -- where do the cost and the failure come from?

level: seniorimportance: should knowfreq 14%

answer

  1. The hook runs inline on the caller's thread
  2. No hooks installed is nearly free
  3. Every hook sees every event and filters in Python
  4. Filesystem writes inside a hook re-enter it
  5. An exception in the hook aborts the audited call

basics

~20 s

Installing any hook turns every audit point into a Python call plus a tuple, and the hook sees all events, not just its own. The abort is worse: an exception inside the hook propagates out of the audited operation.

solid answer

~50 s

Two separate problems share one cause -- the hook runs inline, on the caller's thread, inside the audited operation. **Cost:** with no hooks installed an audit point is a flag check that does not even build its argument tuple; with one hook installed, every `"open"`, `"import"` and `"compile"` in the run becomes a Python-level call, and the hook filters in Python because there is no per-event subscription. In an export loop that opens a file per partition, that multiplies by row count. **Failure:** the hook formatted the path from the `"open"` event into a log stream whose encoding could not represent it, the `UnicodeEncodeError` propagated out of `open()`, and the export died six hours in. Fix both by making the hook's first line a cheap name test, doing no I/O inline, and wrapping the body in `try`/`except` so telemetry can never abort work.

code

python · 11 lines
python
import sys

def logging_hook(event, args):
    if event == "open":
        sys.stdout.write(args[0].encode("ascii").decode() + "\n")

sys.addaudithook(logging_hook)
try:
    open("/tmp/naïve-export.csv", "w", encoding="utf-8").close()
except UnicodeEncodeError as exc:
    print("open() failed inside the hook:", type(exc).__name__)

go deeper

for a junior

Remember that the hook runs inside the operation it reports on: whatever it does is added to that operation's time, and whatever it raises comes out of that operation.

for a middle

Explain the two cost regimes -- an audit point with no hooks installed is a flag check, and one installed hook makes every audit point a Python call plus a tuple -- and why filtering has to be the first line of the hook.

for a senior

Demonstrate the diagnosis: count events before tuning, keep the hook to a cheap name test and a bounded append, swallow exceptions so telemetry can never abort work, and never do inline I/O that re-enters the hook.

for a principal

Own the rule for the fleet: since a hook cannot be removed at runtime, its failure modes are a production risk you accept at deploy time, so mandate a bounded, non-raising, non-blocking hook body and keep policy in data rather than in the closure.

## Why the hook is on the critical path An audit hook is not a listener on a queue. `sys.audit` calls each installed hook synchronously, on the thread that raised the event, before the audited operation proceeds. Everything the hook does is therefore latency added to that operation, and everything the hook raises is an exception thrown by that operation. A nightly export that opens files, imports lazily and shells out is raising audit events continuously, and a hook you installed for security telemetry has quietly become a participant in the data path. ## Where the time goes With **no** hooks installed, the interpreter's audit points are close to free: the C-level audit call checks whether any hooks exist and returns without even constructing the argument tuple. This is why the instrumentation can be compiled in unconditionally. Install **one** hook and three costs appear at every audit point in the whole process: 1. The argument tuple is now built. 2. A Python-level call happens, with frame setup and teardown. 3. Whatever the hook body does runs -- for every event, because there is no way to subscribe to a subset. Filtering is your code's job, in Python, on the hot path. Install five hooks and you pay steps 2 and 3 five times. The multiplier is the event volume, and in a long batch job that volume is dominated by whichever operation sits inside the innermost loop -- typically `"open"` if the job reads or writes a file per unit of work. The measurement discipline is simple and should come before any tuning: install a hook that does nothing but tally event names into a counter, run a representative slice of the workload, and print the totals. Now you know which events dominate, and whether the hook is even on the hot path. Then compare wall-clock time for the slice with and without the hook installed. Guessing which event is hot is how people optimise the wrong branch. ## Writing a hook that is cheap * Make the **first statement** the cheapest possible discriminator: membership in a module-level `frozenset` of event names, or a `str.startswith` prefix test, with an immediate `return` otherwise. Every microsecond here is multiplied by total event count. * Do **no formatting** on the hot path. Building an f-string for an event you are about to discard is pure waste; build strings only after the filter has passed. * Do **no I/O inline**. Writing to a file from inside a hook raises the `"open"` event, which re-enters your hook; sending over a socket raises socket events. Append to a bounded in-memory buffer or a `queue.Queue` and let a separate consumer thread drain it, so the audited operation pays an append and nothing more. * Accept **lossy** telemetry. A bounded buffer that drops when full is the right shape for a hook: dropping an event is always better than slowing or breaking the workload. ## Where the abort came from The second failure is the more dangerous one and is not about performance at all. An exception raised inside a hook is not caught by the interpreter on your behalf: it propagates out of whatever operation raised the event. A hook that crashes on the `"open"` event makes `open()` itself raise. The concrete shape here is an encoding mismatch. The hook took the path out of the `"open"` event's arguments and wrote it to a log stream that could not encode every character in it -- a filename carrying non-ASCII bytes against a stream whose encoding was narrower. `UnicodeEncodeError` came out of the hook, out of `open()`, and up through the export, six hours into a run, at whichever partition first carried an unusual filename. Nothing in the traceback obviously says "audit hook"; it looks like the export failed opening a file. The general rule: **an audited operation inherits every failure mode of your hook.** Two defences, applied together: * Wrap the entire hook body in `try`/`except Exception` and swallow, unless the hook exists specifically to enforce policy -- in which case exactly one narrow, deliberate raise is allowed and everything else is still swallowed. * Remove the failure modes you can: never rely on a default encoding when writing paths, specify the encoding and `errors="replace"` explicitly, and treat every value in the `args` tuple as arbitrary bytes-shaped data rather than as something printable. And remember the constraint that makes this urgent: the hook cannot be uninstalled. There is no runtime remedy for a hook that raises -- the process is restarted or the job keeps dying. ## Choosing the right tool at all If the goal is finding where the export spends its 6 hours, the audit stream is the wrong instrument: it reports security-relevant operations, not call frequency or time, and it charges you for every event in the process to do it. Reach for it when you want to know *what sensitive operations happened*; reach for the interpreter's profiling and monitoring facilities when you want to know *where time went*.

  • How would you measure the hook's real cost before tuning it?
    First install a hook that only tallies event names into a counter and run a representative slice of the job: that tells you which events dominate and whether your hook is even on the hot path. Then time the same slice with and without the hook installed. Both steps are cheap, and they stop you optimising a branch that fires a hundred times when `"open"` fires a hundred thousand.
  • Why is writing the audit record to a file from inside the hook a trap?
    Opening or writing a file raises the `"open"` event, which re-enters your own hook, so the hook feeds itself and can amplify or recurse. Inline I/O also puts disk or network latency directly into every audited operation. The safe shape is to append to a bounded in-memory structure inside the hook and drain it from a separate consumer, accepting that a full buffer drops records.
  • Should a hook ever be allowed to raise?
    Only when raising is its purpose -- a deliberate policy such as refusing `"subprocess.Popen"` in a service that must never shell out. Then the raise is one narrow, intentional branch and the rest of the body is still wrapped so no incidental bug can abort unrelated work. A hook that exists for telemetry should be incapable of raising, because it cannot be uninstalled if it starts doing so.

saying these in an interview costs you the question

  • Thinks the hook runs on a background thread
  • Assumes an exception in the hook is swallowed by the interpreter
  • Believes audit points cost the same with and without hooks
  • Writes log files directly from inside the hook
  • Expects to subscribe only to the events it needs
  • Formats every event before checking the event name

context

resolving links…