Skip to content

Add per-stage metrics for dramatiq tasks - #1264

Open
anfimovdm wants to merge 1 commit into
masterfrom
dramatiq-task-stage-metrics
Open

anfimovdm wants to merge 1 commit into
masterfrom
dramatiq-task-stage-metrics

Conversation

@anfimovdm

Copy link
Copy Markdown
Contributor

Part of AlmaLinux/build-system#553. Fixes AlmaLinux/build-system#558.

The only per-task data for the dramatiq workers was the built-in dramatiq_message_duration_milliseconds histogram. Over the last week execute_release_plan averaged 164s, release_new_errata 173s and bulk_errata_release 358s, but there was no way to tell whether that time goes to the queue, the database, Pulp, or our own code.

Changes

New alws/utils/task_metrics.py. TaskMetricsMiddleware gives each message a timing context held in a context variable. Hooks add the time they spend to it, and the middleware publishes it when the message finishes:

Metric Labels Meaning
albs_task_queue_wait_seconds actor enqueue → a worker starts the message
albs_task_duration_seconds actor wall time; buckets 0.5s–1h, no 60s→600s gap
albs_task_component_seconds actor, component db, pulp_db, pulp_http, pulp_semaphore, pulp_task_wait, business (the remainder)
albs_task_db_queries actor SQL statements per message
albs_task_stage_seconds actor, stage named business steps (they nest; don't sum them)
albs_pulp_request_seconds method, endpoint, status Pulp latency, endpoint templated with {id} / {n}
  • alws/dramatiq/__init__.py: registers the middleware and SQLAlchemy cursor hooks on the Engine class (covers the sync engine inside each async engine).
  • alws/utils/pulp_client.py: request() records HTTP time and semaphore wait separately; wait_for_task() polling counts as pulp_task_wait; get_repo_modules_yaml(), which bypasses request(), is timed too.
  • alws/utils/measurements.py: class_measure_work_time_async also reports its ~16 release planner steps as stages.
  • alws/release_planner.py, alws/crud/errata.py: stages for signature checks, CAS, module lookup, Pulp modify/publish, Pulp package lookup, updateinfo preparation, package matching, OVAL generation, release log and GitHub issue creation.

Things worth reviewing

  • Not a second Prometheus middleware. Registering dramatiq's Prometheus() again duplicated collectors and conflicted on :9191 (c35f672). This is a separate class with no forks and only albs_* names; the existing exposition server already serves everything in the multiprocess directory. A test asserts Prometheus stays registered exactly once.
  • prometheus_client is imported lazily. It picks in-memory or multiprocess storage on first import, and dramatiq only sets PROMETHEUS_MULTIPROC_DIR in after_process_boot, after alws.dramatiq is imported. An eager import made every worker metric, dramatiq_* included, disappear from :9191. The histograms are now created on first use, so no compose/env change is needed, and a test checks that importing alws.dramatiq does not import prometheus_client.
  • Metrics never break the caller. Failures are logged and swallowed in the middleware, the DB hooks, Pulp requests and stages.
  • Concurrent calls are summed per component (asyncio.gather over Pulp calls), so components can exceed wall time; business is clamped at zero. Stage timings are wall-clock and exact.

Testing

  • New tests/test_unit/test_task_metrics.py (21 tests): middleware accounting and skip path, context shared across gather, stages inside and outside tasks, class_measure_work_time_async, query counting and recovery after a failed statement, ALBS vs Pulp DB classification, real PulpClient requests against a local aiohttp server (semaphore split, polling accounted as task wait, error status label), endpoint templating, the single-Prometheus guard, the import-order guard, and metrics failures not reaching callers.
  • Full suite: 147 passed, 10 skipped (pytest --ignore tests/test_oval against Postgres 13).
  • End to end with RabbitMQ and dramatiq --processes 2, both with and without PROMETHEUS_MULTIPROC_DIR in the environment: all albs_task_* series are served on :9191, dramatiq_messages_total is 3 for 3 messages (no double counting), and there are no port conflicts.

Follow-ups

  • Errata publication polls Pulp every 30s (process_errata_release_for_repos, update_errata_references_in_pulp), so a publication finishing in 31s is noticed after 60s. pulp_task_wait should make this visible.
  • Dashboard panel stacking albs_task_component_seconds per actor once this is deployed.

The only per-task data for the workers was dramatiq's built-in duration
histogram. Releases and errata releases take 2-6 minutes on average, but
there was no way to tell whether that time goes to waiting in the queue,
the database, Pulp, or our own code.

TaskMetricsMiddleware gives each message a timing context held in a
context variable. dramatiq calls before_process_message and the actor in
the same worker thread, and run_until_complete and asyncio.gather copy the
context into every task, so all of them add to the same object.

- SQLAlchemy cursor events on the Engine class time every statement and
  count queries, split into the ALBS DB and the Pulp DB.
- PulpClient.request records HTTP time and the wait for the client
  semaphore separately; wait_for_task polling is accounted as
  pulp_task_wait. get_repo_modules_yaml, which bypasses request(), is
  timed too.
- When the message finishes, the middleware publishes queue wait, total
  duration (buckets 0.5s-1h, so 1-10 minute tasks are no longer
  interpolated across a single 60s-600s bucket), per-component time,
  business time (the remainder) and the query count.
- Named stages: class_measure_work_time_async now also reports its ~16
  release planner steps, and the release and errata flows mark their
  main steps (signature checks, Pulp package lookup, modify and publish,
  updateinfo preparation, OVAL generation, release log).
- albs_pulp_request_seconds records Pulp latency per method, templated
  endpoint and status.

The middleware is a separate class from dramatiq's own Prometheus
middleware, which the broker already installs: it has no forks, uses
albs_* names, and its samples are served by the existing :9191
exposition server. A test guards that Prometheus stays registered once.

prometheus_client is imported lazily. It picks in-memory or multiprocess
storage on first import, and dramatiq only sets PROMETHEUS_MULTIPROC_DIR
in after_process_boot, after alws.dramatiq is imported. An eager import
made every worker metric, dramatiq_* included, disappear from :9191; a
test now checks that importing alws.dramatiq does not import
prometheus_client.

Metrics failures are swallowed everywhere, so they cannot fail a query,
a Pulp request or a release. Concurrent calls are summed per component,
so components can exceed wall time; business is clamped at zero.

Related to AlmaLinux/build-system#558
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.

Add per-stage metrics for dramatiq tasks

1 participant