Hacktoberfest 2026: le issue che i maintainer hanno segnato per ottobre, aperte e adatte ai principianti. Sfoglia le issue Hacktoberfest

Per-task logging costs a third of worker throughput

Chiusa
  • Qualcosa non va?
#68 0 commenti 0 reazioni 0 assegnatari Vedi su GitHub

I maintainer di solito rispondono entro 1 giorno

Nessuno ha ancora preso questa issue.

Valutazione

Difficoltà
3/5
Tempo stimato
1-2 giorni
Idoneità per principianti
68/100
Tipo di issue
Bug
Chiarezza
Abbastanza chiara
Stato di attività
Attiva
Stack tecnologico
django, python, redis
Ambito
backend, cli, observability, performance

Direzione di ricerca

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.

Scritto dal modello di indicizzazione a partire dal testo della issue.

Descrizione

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.

Lingua principale
Python
Stelle
21
Fork
2
Merge medio
12h 38m
PR unite (30g)
27

Preparare l'ambiente

Come iniziare

  1. Leggi tutta la issue e poi la guida ai contributi del progetto.
  2. Commenta sulla issue per dire che te ne occupi tu — evita che due persone facciano lo stesso lavoro.
  3. Fai un fork del repository e lavora su un branch.
  4. Apri una pull request che faccia riferimento al numero della issue.

Issue simili

Altre issue su Python

Ricevi le nuove issue nella tua casella

Un breve riepilogo di issue GitHub adatte ai principianti.