Log why a substreams request is slow, while it is still running

[sduchesneau]

Why

The final substreams request stats log only lands once a request is over — too late to answer "why is my substreams slow?" while it is still running. Tier1 now emits a bounded summary per request: once after 1 minute, then every 5 minutes.

Three commits:

1. Report failing and in-flight external calls from tier2 — proto change
2. Add a tools command to simulate a slow reading consumer
3. Log why a request is slow, every 5 minutes — the progress log itself

The line

A line from a request mid-backprocessing, trimmed to one stage and two hints:

{
  "trace_id": "35cc603abf24977a434f5090f2447b6d",
  "output_module": "graph_out", "production_mode": true,
  "phase": "parallel_processing", "elapsed": "42m0s",
  "last_sent_block": 12369738, "last_block_in_cache": 12450000,
  "blocks_sent": 118,
  "blocks_sent_5m": { "blocks": 118, "blocked": "5ms", "avg_per_block": "39µs", "longest_stall": "59µs" },
  "stages": [
    {
      "stores": ["uni:store_pool_count", "uni:store_pools_created", "uni:store_tokens"],
      "mappers": ["uni:map_pools_created"],
      "ready_up_to": 12600000,
      "squash_wait_segments": 37,
      "jobs": {
        "start": 12369621, "end": 12800000,
        "completed": 12, "completed_5m": 12,
        "running": 1, "oldest_running": 12600000, "oldest_running_at": 12600512,
        "oldest_running_age": "9m0s", "avg_dur": "4m0s"
      }
    }
  ],
  "external_calls": [
    { "module": "uni:map_pools_created", "extension": "rpc:eth_call",
      "count_total": 4, "total_time": "14m0s",
      "count_5m": 0, "time_5m": "5m0s", "avg_5m": "0s",
      "calls_still_running": true, "at_block": 12600512 }
  ],
  "last_job_error": {
    "stage": 2, "age": "1m30s", "count_total": 1, "count_5m": 1,
    "error": "… running wasm extension \"rpc::eth_call\": timeout while doing eth_call, waiting for rpc provider for 3m0s (29 attempt(s), last error: … dial tcp [::1]:8545: connect: connection refused)"
  },
  "hints": [
    "module \"uni:map_pools_created\" spent 5m0s of the last 5m0s inside rpc:eth_call calls without a single one completing on block 12600512: at least one call has been waiting for the whole window, so the endpoint behind it is unreachable or far too slow and the segment will eventually time out on it",
    "stage 2 covered 739 of the 10000 blocks of segment [12450000, 12460000) in 22m0s (1.79s per block): at that rate the segment needs about 4h58m0s, where 1 to 10 minutes is expected"
  ]
}

• phase — where the client's blocks come from right now: streaming_first_segment (a tier2 worker streaming the first mapper segment live, the usual start of a production request), parallel_processing (the exec-out cache), linear_processing.
• stages[] — the stores and mappers the stage executes, ready_up_to (the lowest contiguous block across its modules — a stage is only as advanced as its least advanced one; for stores it stops at the last squashed segment), squash_wait_segments, and a jobs block: the range the plan says it must cover, completions, and where the oldest running job started and got to.
• external_calls[] — per module and extension, with calls_still_running and the at_block it is holding up.
• last_job_error — the worker error text, which tier1 had been logging once and dropping.
• blocks_sent_5m — blocked is total time inside SendMsg; the outliers are named longest_stall because SendMsg returns as soon as the message fits the gRPC flow-control window and blocks only when it fills, so a single stall measures the buffer as much as the client.

What it looks like in practice

Three situations reproduced against a local stack.

1 — A tier2 segment that will never finish in time

Called out in the first minute from the rate the job is holding, not fifteen minutes later from its age:

stage 1 covered 36 of the 1000 blocks of segment [1000, 2000) in 57.02s (1.58s per block): at that rate the segment needs about 26m0s, where 1 to 10 minutes is expected

"jobs": {
  "running": 2,
  "oldest_running": 1000,
  "oldest_running_at": 1036,
  "oldest_running_age": "57.02s"
}

2 — eth_calls hung while the first segment streams from tier2

module "uni_v0_2_9:map_pools_created" has 4 rpc:eth_call call(s) still waiting for an answer on block 12369739, the oldest for 2m46s: the endpoint behind that call is unreachable or far too slow, and the segment will eventually time out on it

stage 0 covered 78 of the 1000 blocks of segment [12370000, 12371000) in 2m47s (2.14s per block): at that rate the segment needs about 36m0s, where 1 to 10 minutes is expected

"phase": "streaming_first_segment",
"external_calls": [
  {
    "module": "uni_v0_2_9:map_pools_created", "extension": "rpc:eth_call",
    "count_total": 4, "total_time": "10m40s",
    "count_5m": 0, "time_5m": "9m30s", "avg_5m": "0s",
    "in_flight": 4, "oldest_in_flight": "2m46s",
    "calls_still_running": true, "at_block": 12369739,
    "calls_per_block": 0
  }
],
"jobs": {
  "running": 1,
  "oldest_running": 12369000,
  "oldest_running_at": 12369739,
  "oldest_running_age": "2m51s"
}

This is the case the whole PR started from. Note in_flight: 4 and oldest_in_flight on a module executing inside a tier2 job — that is the new proto fields at work. Before them, tier2 reported counts and totals only: the four hung calls contributed no time, the job looked idle, and nothing was known until the segment timed out minutes later. count_5m: 0 with time_5m: 9m30s is the signature of calls that started before the window and never came back.

3 — A slow reading client

Reproduced with substreams tools simulate-slow-reader:

2m47s of the last 3m7s were spent blocked writing to the consumer (627ms per block on average, longest single stall 38.04s): the client or the network is the bottleneck, not the processing

"blocks_sent_5m": {
  "blocks": 266,
  "blocked": "2m47s",
  "avg_per_block": "627ms",
  "longest_stall": "38.04s"
}

blocked (89% of the window) is what triggers the hint. longest_stall is deliberately not the trigger: SendMsg returns as soon as the message fits the gRPC flow-control window and blocks only when it fills, so a 38s stall measures the buffer draining at the client's pace as much as the client itself.

The window is decoupled from the emission interval

Every _5m value covers a fixed trailing 5 minutes, accumulated in 30s time buckets addressed by absolute time. Reading sums the in-window buckets and does not consume them, so two consecutive lines are always comparable and SUBSTREAMS_PROGRESS_LOG_INTERVAL changes only how often the line is printed, never what the numbers mean. On a request younger than 5 minutes the values cover its lifetime, which elapsed makes explicit.

Hints

Nine, capped at 6 per line. They are deliberately hard to trigger — a hint that fires on a healthy request is worse than no hint at all. Two cases are worth calling out because the obvious signal is wrong:

• A full cache lead is not a slow consumer. The scheduler pins the exec-out cache a fixed distance ahead (maxParallelJobs * 3/2 segments), so a healthy request sits at that ceiling permanently. The consumer is blamed only for time actually spent blocked inside SendMsg (≥35% of the window).
• A throttled scheduler is not a symptom. The first stage has no dependencies, so it runs ahead until it hits that same limit and stays there. The limit exists so a request whose output is not advancing does not burn workers on segments nobody may read — whoever is holding it back. jobs_throttled_5m is reported as context and never generates a hint.

A slow segment is projected from the rate a job is holding (age × segmentSize / progressBlocks) rather than waited out, so a segment that will need half an hour is called out in its first minute instead of fifteen minutes later.

Tier2 reporting (proto change)

pbssinternal.ExternalCallMetric gains four additive fields:

uint64 failed_count           = 4;
uint64 in_flight_count        = 5;
uint64 oldest_in_flight_ms    = 6;
uint64 oldest_in_flight_block = 7;

An eth_call retrying against an unreachable endpoint is a single wasm extension call that can last minutes, and tier2 only emitted progress when a block completed — so tier1 saw an idle job with no external call metrics until the segment finally timed out. Tier2 now reports every 10s while a block is in flight, and counts the time already spent by a call that has not returned.

⚠️ pb/sf/substreams/intern/v2/service_vtproto.pb.go carries ~200 lines of unrelated codegen drift alongside the 4 fields (the vtproto plugin changed how it emits CloneVT). Semantically equivalent. All other generated files were reverted so the churn is contained to the one package.

Sending progress from a ticker goroutine also required a mutex in tier2ResponseHandler — it was doing bare concurrent streamSrv.Send, which gRPC forbids. Latent bug, now load-bearing.

Testing it

substreams tools simulate-slow-reader <manifest> [<module>] --delay 2s -e … --plaintext

Waits before handling each block, blocking the receive loop — the gRPC window fills and the server blocks on sending. Sleeping in a goroutine would exert no back-pressure.

Cost

Stages.computeStageStats folds the contiguous-prefix and pending-partials computation into the existing once-per-second pass over the segment matrix — no additional O(segments × stages) walk. Everything else is O(1) per record call. The line's size is bounded regardless of run length: 20 modules, 12 stages, 5 external-call rows, 6 hints, one 900-char job error.

Notes

• The existing substreams request stats final log is untouched (it feeds reporting systems).
• go test ./... and go test -race pass. go test -race ./test/ fails identically on clean develop — pre-existing, unrelated.

🤖 Generated with Claude Code

[sduchesneau]

🔍 Vulnerabilities of ghcr.io/streamingfast/substreams:235a6c3

📦 Image Reference ghcr.io/streamingfast/substreams:235a6c3

digest	sha256:6b7a4acf263a3da8b4e42440e560e5c1050395a89da3d6ec7540b974d3c5f7e1
vulnerabilities
platform	linux/amd64
size	121 MB
packages	381

📦 Base Image oisupport/staging-amd64:24.04

also known as	a215e986b44aae6f10795ded1e39ce93d9c236d8163d21a522ffd0ab3659f546 noble noble-20260730.1
digest	sha256:019e8eb29a85e74d64925745884f2ec79aa27e3feab36353d24656f4d6b89467
vulnerabilities