Hacktoberfest 2026: as issues que os mantenedores marcaram para outubro, abertas e boas para iniciantes. Ver issues do Hacktoberfest

Per-task logging costs a third of worker throughput

Fechada
  • Algo errado?
#68 0 comentários 0 reações 0 responsáveis Ver no GitHub

Mantenedores costumam responder em até 1 dia

Ninguém assumiu esta issue ainda.

Avaliação

Dificuldade
3/5
Tempo estimado
1-2 dias
Facilidade para iniciantes
68/100
Tipo de issue
Bug
Clareza
Razoavelmente clara
Status de atividade
Ativa
Stack de tecnologia
django, python, redis
Domínio
backend, cli, observability, performance

Direção de pesquisa

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.

Escrita pelo modelo de indexação a partir do texto da issue.

Descrição

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.

Linguagem predominante
Python
Estrelas
21
Forks
2
Merge médio
12h 39min
PRs com merge (30d)
27

Preparar o ambiente

Primeiros passos

  1. Leia a issue inteira e depois o guia de contribuição do projeto.
  2. Comente na issue dizendo que vai assumir — evita que duas pessoas façam o mesmo trabalho.
  3. Faça um fork do repositório e trabalhe em uma branch.
  4. Abra um pull request que referencie o número da issue.

Issues semelhantes

Mais issues de Python

Receba novas issues na sua caixa de entrada

Um resumo curto de issues do GitHub para quem está começando.