Skip to content

Log the duration of each run #3

Description

@ericof

Proposal

Log how long each run took, and ideally how long each phase took — filestorage
and blobs separately.

zodb-backup reports no duration today. Searching src/zodb_backup/ for
elapsed, duration, perf_counter and monotonic, the only hits concern the
monotonicity of backup filename timestamps, not measuring time.

Why in the tool, and not in the orchestrator

Because the orchestrator keeps this only incidentally, and discards it quickly.
Observed in production on cm-uberlandia (Docker Swarm + swarm-cronjob):

  • The container is deleted within the hour. The exact measurement
    (State.StartedAtState.FinishedAt) is the best available, but an hourly
    docker container prune -f cron — a common housekeeping pattern — removes it.
    And it fails silently: inspect answers "No such object", which does not
    distinguish "never ran" from "was swept up".
  • The task record survives, but is bounded and imprecise. The daemon's
    --task-history-limit keeps 5 tasks per slot by default, and the
    CreatedAtStatus.Timestamp interval bundles in scheduling latency and
    image pull time.
  • docker service ps only gives a rounded relative time ("Complete 4
    minutes ago").

The tool is in the privileged position: it knows exactly when it started and
finished, and its log is the one artefact whose retention the operator controls.

Why split the phases

On cm-uberlandia the blobstorage is 48 GB against 3.8 GB of filestorage — the
blobs dominate the run time completely. An aggregate number says the backup got
slower; a per-phase number says whether the database grew or whether the blob
rsync stopped benefiting from hard links.

What this is used for in practice

  • Sizing maintenance windows. Backup and zeopack must not overlap, so
    scheduling both depends on knowing how long each takes. Today that is measured
    with a stopwatch on the first run and never revisited.
  • Catching silent regressions. A backup that goes from 20 minutes to 3 hours
    still exits 0.
  • Alerting. Duration is the metric that signals trouble before an error
    surfaces.

Suggested scope

One line at the end of a successful run, at INFO, with the total and the
phases. No structured metrics, no endpoint — just the log.

Failures should report it too: how long it took to give up is often more
informative than a success.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions