Skip to content

perf(log): opt-in background writer for logger and access-log lines - #370

Merged
gg582 merged 1 commit into
devfrom
perf/async-logger
Oct 13, 2026
Merged

gg582 merged 1 commit into
devfrom
perf/async-logger

Conversation

@gg582

@gg582 gg582 commented Oct 13, 2026

Copy link
Copy Markdown
Member

Summary

Logging on the request path cost a lot once several threads logged at once.

  • cwist_logger_* wrote each line with three fprintf calls and an fflush, so every line was at least one syscall.
  • The access-log middleware called printf under a global mutex.
  • With 8 threads, one line cost the calling thread about 12.5 µs.

This PR adds an opt-in background writer. Logging stays synchronous unless the app calls cwist_log_async_start().

Changes

  • New API (include/cwist/sys/app/logger.h): cwist_log_async_start(size_t), cwist_log_async_flush(), cwist_log_async_stop(), cwist_log_async_active(). The API baseline is regenerated with additions only; no existing struct or signature changes.
  • src/sys/app/log_async.c:
    • One writer thread and one byte ring per stream (stdout, stderr). A caller formats the whole line on its stack, copies it into the ring under one mutex and returns. The writer does the write() calls.
    • Each line stays whole, and lines on one stream keep their order.
    • A full ring makes the caller wait. Nothing is dropped.
    • A line larger than the ring, or any line while the writer is off, is written synchronously as before.
    • pthread_atfork: a forked child (CWIST_WORKERS) drops its copy of the parent's queue and starts its own writer on its first line.
    • atexit writes whatever is still queued.
    • WASM builds get stubs, so start returns false.
  • logger.c: builds the whole line once, then queues it or writes it with one fwrite. The output format is unchanged. The timestamp is cached per thread per second: localtime_r() takes glibc's timezone lock on every call and was the largest cost left with 8 threads.
  • middleware.c: the three access-log formats go through one helper, access_log_printf(), which queues the line or fwrites it under the existing mutex.
  • Docs: docs/api/middleware.md and docs/ko/api/middleware.md get an "Async log output" section.

Measurements

Local machine, 12 cores. Each thread logs one ~70-byte line repeatedly to a file. Per-line cost is wall time per line as each calling thread sees it.

Threads Mode Cost per line, ring never fills (1,000 lines per thread) Throughput incl. drain (200,000 lines per thread)
1 sync 1.3 µs 0.91 Mlines/s
1 async 0.55 µs 2.80 Mlines/s
8 sync 12.5 µs 0.64 Mlines/s
8 async 2.6 µs 4.64 Mlines/s

Tests

  • New tests/test_log_async.c, wired into TEST_TARGETS. It covers:
    • 8 threads logging 16,000 lines through a 4 KiB ring (so callers wait often). Every line is whole and each thread's lines are in order on stdout and on stderr.
    • A line larger than the ring falls back to a synchronous write. stop drains the queue, and logging after stop is synchronous again.
    • The JSON access log goes through the writer.
    • A forked child starts its own writer, its line is written by exit(), and the parent's queued line is written exactly once.
  • TSan: the test sets die_after_fork=0, because TSan otherwise refuses to start a thread after a multi-threaded fork, which is exactly the worker case this tests.
  • Local runs (built against an existing libcwist.a with the three changed files linked first):
    • test_log_async: 50 runs, all passed.
    • test_log_async under TSan (changed files and test instrumented): 30 runs, no failures and no race reports.
    • test_logger_config and test_access_log: pass.
  • Gates: check_api_baseline, check_api_test_coverage, check_env_knobs, check_test_wiring, malloc_lint and clang-format all pass.
  • Not run locally: the full make test suite. CI covers it.

cwist_logger_* wrote each line with three fprintf calls and an fflush,
and the access-log middleware printf'd under a global mutex, both on the
request thread. With 8 threads logging, a line cost the caller ~12.5 us.

cwist_log_async_start() starts one writer thread with a byte ring per
stream (stdout, stderr). A caller formats the whole line on its stack,
copies it into the ring under one mutex and returns; the writer does the
write() calls. Lines stay whole and in order per stream, a full ring makes
the caller wait (nothing is dropped), and a line larger than the ring, or
any line while the writer is off, is written synchronously as before.
pthread_atfork gives forked workers their own writer, an atexit hook
writes what is still queued, and WASM builds get stubs that never start.

The logger also caches its timestamp per thread per second: localtime_r()
takes glibc's timezone lock on every call and was the largest cost left
once many threads log.

Logging stays synchronous unless cwist_log_async_start() is called. New
API: cwist_log_async_start/flush/stop/active (baseline regenerated).
@gg582
gg582 merged commit f00cafd into dev Oct 13, 2026
25 checks passed
@gg582
gg582 deleted the perf/async-logger branch October 13, 2026 06:47
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant