perf: lifecycle logging costs ~107 us/record, about 20x stdlib

[codeforester]

Problem

A log record through the base-cli lifecycle costs roughly 20x what stdlib logging costs. Two
independent per-record costs compound:

1. A lock file is opened, locked, unlocked, and closed for every record.
SecureLogFileHandler.emit() (lib/python/base_cli/logging.py:140-147) calls
_open_log_lock() → mkdir(parents=True, exist_ok=True) + open("a+b") + restrict_file(),
then flock(), then super().emit(), then unlock and close(). That is a fresh file open,
chmod, and advisory lock acquisition per log line.

A second problem hides in the same method: if _open_log_lock() raises — the log directory
becomes unwritable or the volume fills mid-run — the OSError propagates out of the caller's
logger.info(...) call instead of going through Handler.handleError(). A logging call can
therefore fail the command.

2. Every record does multiple Path.resolve() syscalls. CliFormatter.format() calls
_source_path() (lib/python/base_cli/logging.py:224-240), which calls
get_current_context() twice (via _active_application_home() and _active_project_root()),
then path.resolve() on the record's pathname and root.resolve() for each candidate root, per
record. Nothing is cached, although the candidate roots are fixed for the whole invocation.

No benchmark scenario measures this: every scenario in scripts/benchmark_runtime.py logs zero or
one records, so the documented budgets in docs/performance.md cannot detect a throughput
regression. (#309 completed the scenario set for invocation cost; log throughput was not part of it.)

Verified evidence

Reviewed 2026-09-30 at a58ec109349fa3f3d03eae5b0de078b39ea361a2 (macOS, Python 3.14.6, Click 8.4.2).

Component measurements, 2000 records each:

Path	Cost	vs stdlib
SecureLogFileHandler.emit	42.3 us/record (23,645 rec/s)	15.4x
stdlib FileHandler.emit	2.7 us/record (365,075 rec/s)	—
CliFormatter.format	62.1 us/record	36.5x
stdlib Formatter.format	1.7 us/record	—

End-to-end through a real App with default persistent logging, 3000 ctx.log.info() calls:

3000 ctx.log.info calls: 322.4 ms -> 107.5 us/record, 9,305 rec/s

A command that logs 100k lines — routine for a reconciliation or inventory job — spends about
11 seconds in logging overhead alone.

Proposal

1. Hold the lock file open for the handler's lifetime instead of per record; acquire and release
   the advisory lock around each write. O_APPEND writes under flock do not need a fresh
   descriptor per record. Consider dropping the sidecar entirely on POSIX where O_APPEND writes
   below PIPE_BUF are already atomic, keeping the sidecar only where it is needed.
2. Route emit() failures through self.handleError(record) so a logging call can never fail the
   command.
3. Cache the resolved candidate roots on the formatter (or in the Context) for the invocation,
   and cache resolved record pathnames in a small bounded dict keyed by record.pathname — module
   paths repeat constantly.
4. Add a log-throughput scenario to the benchmark with a p95 budget (see the companion CI issue).

Acceptance criteria

• ctx.log.info() through a persistent-logging App costs under ~15 us/record on the calibration
  host, and the benchmark gates it.
• _source_path() performs no filesystem syscalls in the steady state for repeated pathnames.
• A handler failure mid-run produces a logging-internal error, not a failed command; a regression
  test makes the log directory unwritable mid-invocation and asserts the command still completes.
• Output format of both CliFormatter and JsonLogFormatter is byte-for-byte unchanged.

Non-goals

• Do not weaken the 0600 file mode or the cross-process append safety the sidecar provides.
• Do not switch to asynchronous logging; ordering and flush-on-exit guarantees must hold.