[morgan-wowk]

Problem

Each visit of the running sweep logs three INFO lines, even when nothing changed. At 300–1000 active executions, that is tens of lines per second of noise. If the sweep hangs, the flood just stops, and nothing makes that easy to alert on.

Objective

Log only what carries information. The per-visit durations now come from the container_execution.refresh.duration metric added in #425.

sequenceDiagram
    participant Sweep as Orchestrator sweep
    participant Logs
    participant Metrics

    loop Every running container execution visit
        Sweep->>Metrics: refresh.duration (queries, processing)
        alt Queries or processing over 1s
            Sweep->>Logs: Slow running container execution visit
        else Normal visit
            Note over Sweep,Logs: No log line (before: 3 INFO lines)
        end
    end
    Sweep->>Logs: Orchestrator heartbeat, about once a minute, with queued and running counts
    Note over Logs: A missing heartbeat means the sweep stopped

Loading

Changes

• Removes the three per-visit INFO lines: Before processing …, … remains in RUNNING state. and After processing ….
• Adds Slow running container execution visit (queries: …ms, processing: …ms). It is logged only when either part takes over 1s, the same threshold the idle-queue log uses.
• Adds Orchestrator heartbeat: processed N queued executions and M running container executions in the last 60s. It is logged even when both queues are idle.
• State changes, terminations, cancellations, retries, exceptions and the orchestrator.process_running_execution span are unchanged.

Testing

• pytest tests: 584 passed. TestHeartbeat covers an idle heartbeat and the counts resetting.
• No test or downstream code matches on the removed messages.

[yuechao-qin]

Is moving this start_timestamp here intentional and any beahviour changes?

[morgan-wowk]

🤖 AI-assisted: Yes, intentional. start_timestamp used to be set before the execution-node-IDs query, so that query was counted in both queries_duration_ms and the processing duration. Setting it after the queries makes the two numbers in the slow-visit line separate, which tells a slow database apart from a slow launcher. No other behaviour changes: duration_ms only feeds that log line.

Also added in f0daa92: a once-a-minute heartbeat (Orchestrator heartbeat: processed N queued executions and M running container executions in the last 60s.). The per-visit lines we removed were the only sign the sweep was alive, so the heartbeat keeps that signal at one line a minute. If it stops appearing, the sweep has stopped.