[morgan-wowk]

Changes

The running queue visits every pending or running container execution in turn, and each visit logged three INFO lines even when nothing changed:

• Before processing running container execution. Queries duration …ms.
• Container execution remains in RUNNING state.
• After processing running container execution (duration: …ms)

This PR removes all three and adds two lines that only appear when they carry information:

• Slow visit, logged only when a visit's queries or its processing take more than 1s:
  Slow running container execution visit (queries: …ms, processing: …ms)
  The 1000ms threshold matches the one the idle-queue log already uses. The queries time covers the select that picks the next execution plus the execution-node lookup. The processing time covers the refresh. Keeping them apart separates a slow database from a slow launcher.
• Heartbeat, logged about once a minute from process_each_queue_once:
  Orchestrator heartbeat: processed 12 queued executions and 1840 running container executions in the last 60s.
  It's logged even when both queues are idle, and only by the orchestrator that is actually sweeping.

Impact

• At 300–1000 active executions, log volume goes from tens of INFO lines per second to about one a minute, plus the lines for real events.
• Business-logic events keep their existing logs: state changes (Container execution is now in state …), terminations, cancellations, retriable refresh failures and exceptions.
• A stopped sweep is now easier to alert on. Before, the only sign the sweep was alive was the per-visit flood, and if a visit hung, the flood just stopped. Now a missing heartbeat means the sweep stopped, and the count shows its throughput.
• A slow running-queue select still shows up while the queue is busy, which the idle-only query_duration_ms log doesn't cover. The orchestrator.process_running_execution trace span is unchanged.

Before / after (500 active executions, steady state, one minute)

Before: about 3 lines per visit, so thousands of INFO lines.
After: 1 heartbeat line, plus one line per slow visit or state change.

Testing

• pytest tests: 576 passed. New tests: TestHeartbeat covers an idle heartbeat after the interval, and counts that reset between heartbeats.
• No test or downstream code matches on the removed messages.

🤖 Generated with Claude Code

[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.