Per-task logging costs a third of worker throughput

Start with threadmill/executor.py, especially configure_logging, the worker command options, and the per-task executor log calls. Trace how TaskExecutor receives logging configuration and how Django's task signal receivers inherit the root level. Done means the worker exposes a configurable level, avoids forcing INFO, and treats per-task executor messages as debug detail while preserving operator control of django.tasks.

Profiling a drain (20,000 echo tasks, one process, one thread, prefetch 128) puts logging at roughly 70 µs of client CPU per task, against a recorded per-task wall of 184 µs. That is about 38% of the worker's throughput, and it is the single largest Python cost in the loop - larger than the Redis round trips it sits next to.

What emits four JSON records per task

• threadmill/executor.py logs Executing task ... and then Task ... succeeded (or failed) at INFO for every task.
• Django's own django.tasks.signals receivers (log_task_started, log_task_finished) log once more each. They are registered at import and sit at NOTSET, so they inherit the root logger's level.
• threadmill/executor.py's configure_logging sets the root logger to INFO unconditionally, so all four records are formatted and written.
• The worker's default formatter is JsonFormatter, which builds a payload dict and json.dumpses it per record, then writes to stdout and flushes.

Measured inside that 70 µs: 51 µs in StreamHandler.emit and 36 µs in JsonFormatter.format/json.dumps - the formatting, not the log call itself. record_task's lock, by contrast, costs 0.35 µs, and normalize_json 0.5 µs.

Why this is a defect and not just a tuning knob

There is no way to quieten a production worker: configure_logging hardcodes root_logger.setLevel(logging.INFO), and the command exposes --log-format but no --log-level. A deployment that wants WARNING output cannot get it, and it pays a JSON encode and a stdout flush per task for the privilege.

Suggested fix

• Add a level option to the worker command (and to TaskExecutor), defaulting to something quiet.
• Demote the two per-task executor records to DEBUG; "task started/succeeded" is trace-level detail, and the task itself is the interesting signal.
• Leave the level of django.tasks to the operator rather than forcing the root logger to INFO.

Benchmark fairness

The comparison harness runs celery and dramatiq with --loglevel=WARNING, while threadmill currently cannot run below INFO, so part of the chart gap is threadmill logging its own benchmark. Fixing this makes the comparison apples-to-apples as well as making production faster.

Discovered while validating per-task performance claims; the profiling numbers are from a loaded machine, so treat the shares as the durable result and the absolute microseconds as this box's.